That usually means you were serialization an array...
# box-products
b
That usually means you were serialization an array which was modified mid-stream by another thread
w
Yes, I understand
b
So whatever struct you passed to your logger is also referenced by another thread which modified it while it was being serialized
I don't know of a "fix" outside of using
duplicate()
when passing it
w
But how? It is just an error which is being logger from an onEntityNotFound or onValidationError
b
Beats me, without seeing the stack trace I don't even know what line of code is logging the error or what it's passing in to the log event
w
So only doing
Copy code
var warning = arguments.exception.message;
        logger.error( warning, arguments.exception );
from some errormethod in a basehandler. I know these logEvents are queued and then processed by some queuehandling thread. But does this mean we can NEVER pass some struct to a logmessage? I mean: always first use duplicate? In that case it would be better if loggers were always duplicating the extrainfo in a message, because you are never use these structs are still there. I only see this in a system under stress (aka using testbox 🙂 ). I guess in other situations the logs have been processed before the struct has been cleared
b
I'm confused how the exception object is being changed by another thread 🤔
Are there two different logbox appenders that may be both processing the extraInfo at the same time?
w
I think yes now. A rollingFileAppender and a modified dbAppender.
b
Ahh, I wonder if one of them is mutation the exception as it logs it
Or perhaps using an iterator internally
It's difficult to troubleshoot this stuff since it happens deep inside of Lucee and the exception is being thrown from concurrent JDK classes
w
I don’t think it is mutating the exception, but I’ll have a closer look tomorrow. And yes, hard to debug, since it is not always happening. I can duplicate the errorinfo though before logging. That would probably solve the issue. But I would rather understand the problem and fix it in a proper way 🤔
I have seen the same kind of behaviour in the past with logging, when I was trying to log some ORM events. Often the ORM entity was gone before I could access it for logging.
Ok @bdw429s I looked at the source and I think if extrainfo is a struct it is passed (by reference?) to all appenders. So not sure what happens exactly but I guess the extrainfo struct is cleaned up before all appenders could process it. I think I can avoid this by duplicating extrainfo before sending it to the queue in my own custom appender. As said this is just a small modification of the dbappender, so I think the problem would still be there for anyone using multiple appenders under some load. I am wondering if I should file a bug for this?
z
def file a bug, if you can provide a repo test case that would be awesome