[Bug 100] New: Serialization of objectArray in LoggingEvent does not always work
http://bugzilla.qos.ch/show_bug.cgi?id=100 Summary: Serialization of objectArray in LoggingEvent does not always work Product: logback-classic Version: unspecified Platform: PC URL: http://www.qos.ch/pipermail/logback-dev/2007- September/002169.html OS/Version: Other Status: NEW Severity: major Priority: P1 Component: Other AssignedTo: logback-dev@qos.ch ReportedBy: noreply.ceki@qos.ch I think this is happening: * Logback is sending a serialized LoggingEvent over the socket * the LoggingEvent has a reference to the foo.bar.Car instance * the Eclipse plugin receives the bytes over the wire and tries to deserialize the LoggingEvent, this fails because the foo.bar.Car class is not on the classpath. Resolution: I think the SocketAppender should only send the formattedMessage over the wire and not the argumentArray. In other words: argumentArray should be declared transient. Let's see what the LogBack developers think about that ... -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 ------- Comment #1 from joern@huxhorn.de 2007-10-23 18:10 ------- Created an attachment (id=11) --> (http://bugzilla.qos.ch/attachment.cgi?id=11&action=view) Changing arguments to Strings before serialization. I just ran into a similar problem on the receiving end, i.e. while deserializing. I'd suggest to fix this problem by converting the contents of this.argumentArray to String prior serialization. That way the args would still be available in case of special handling like translated log messages. -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 joern@huxhorn.de changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |joern@huxhorn.de Severity|major |critical ------- Comment #2 from joern@huxhorn.de 2007-10-24 13:27 ------- I think this problem is critical since it causes the log statements to throw exceptions if the arguments are not Serializable. -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 ------- Comment #3 from joern@huxhorn.de 2007-10-28 14:39 ------- Workaround in SocketAppender: protected void postProcess(LoggingEvent event) { if (includeCallerData) { event.getCallerData(); } // HACK: http://bugzilla.qos.ch/show_bug.cgi?id=100 try { Field field=LoggingEvent.class.getDeclaredField("argumentArray"); field.setAccessible(true); Object aa=field.get(event); if(aa instanceof Object[]) { Object[] argumentArray=(Object[]) aa; for(int i=0;i<argumentArray.length;i++) { Object current=argumentArray[i]; if(current!=null && !(current instanceof String)) { argumentArray[i]=""+current; } } } } catch (NoSuchFieldException e) { e.printStackTrace(); } catch (IllegalAccessException e) { e.printStackTrace(); } } -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 joern@huxhorn.de changed: What |Removed |Added ---------------------------------------------------------------------------- Severity|critical |blocker ------- Comment #4 from joern@huxhorn.de 2008-02-18 11:39 ------- Translation of LoggingEvents - as suggested/requested on the mailing list - would actually be possible quite easily if my fix would be applied instead of the initial resolution idea, i.e. declaring the argumentArray transient. If the argumentArray is serialized as Strings they could still be used in a parameterized message. Translation could be performed using the original unformatted message as the key of the translation. Example: The unformatted message "Executing {} with parameter {} returned {}." could be resolved to "Ergebnis: {2} (Aufruf: {0}({1}))." which could then be formatted using java.text.MessageFormat by a special locale-aware appender. I provided this stupid translation to show that a reordering of message arguments would be possible. I don't think that console appender as such should be extended to provide this functionality but we shouldn't prevent a specialized appender implementation from doing this by simply dropping the argumentArray. I increased the severity to "blocker" because the next logback release should definitely contain a fix for this problem... it causes *very* strange behavior. -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 ------- Comment #5 from joern@huxhorn.de 2008-02-18 12:24 ------- Oops, the discussion was actually on the slf4-mailing-list. The feature request I'm referring is http://bugzilla.slf4j.org/show_bug.cgi?id=50 -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 joern@huxhorn.de changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #11 is|0 |1 obsolete| | ------- Comment #6 from joern@huxhorn.de 2008-03-04 23:31 ------- Created an attachment (id=23) --> (http://bugzilla.qos.ch/attachment.cgi?id=23&action=view) arguments serialization and formattedMessage fix This is a better version of my previous patch (no creation of "null" string). Additionally, I discovered that formattedMessage was not initialized properly if the argumentsArray was initialized by the setArgumentArray method instead of the c'tor. So all in all I changed the following: - removed formatting of message from c'tor. - formattedMessage is initialized lazily in getFormattedMessage. - before the LoggingEvent is serialized, all arguments that are neither null nor a String are converted to String. Also, formattedMessage is cleared since it only occupies space but can be recreated lazily after deserialization. - added LoggingEventTest containing same tests concerning LoggingEvent serialization and formattedMessage. Some will fail without the patch applied. This patch prevents both java.lang.ClassNotFoundExceptions in the deserializer as well as java.io.NotSerializableExceptions in the serializer. -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 noreply.ceki@qos.ch changed: What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |ASSIGNED ------- Comment #7 from noreply.ceki@qos.ch 2008-03-11 10:48 ------- In revision 1641, LoggingEvent now serializes String versions of the data in the arrgumentArray. However, the data in the event itself is not modified. I have not had the time to look into this bug properly. In particular, I have not integrated the test cases found in Joern's patch dated 2008-03-04 23:31 See also http://svn.qos.ch/viewvc?view=rev&revision=1641 -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 joern@huxhorn.de changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #23 is|0 |1 obsolete| | ------- Comment #8 from joern@huxhorn.de 2008-03-11 22:09 ------- Created an attachment (id=24) --> (http://bugzilla.qos.ch/attachment.cgi?id=24&action=view) Added test for arguments containing very large String. Some as the last patch, but added a test that uses a 100.000 char String. This test would fail with the current implementation (revision 1641). -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 ------- Comment #9 from joern@huxhorn.de 2008-03-11 22:15 ------- The changes in revision 1641 won't really solve the original problem but introduces a whole new one instead. The following test case will always fail: package ch.qos.logback.classic; import junit.framework.TestCase; import java.io.*; public class WriteUtfTest extends TestCase { public void testWriteUTF() throws Exception { StringBuffer buffer=new StringBuffer(); for(int i=0;i<100000;i++) { buffer.append("X"); } String string=buffer.toString(); ByteArrayOutputStream bos=new ByteArrayOutputStream(); ObjectOutputStream oos=new ObjectOutputStream(bos); oos.writeUTF(string); oos.close(); ByteArrayInputStream bis=new ByteArrayInputStream(bos.toByteArray()); ObjectInputStream ois=new ObjectInputStream(bis); String read=ois.readUTF(); ois.close(); assertEquals(string,read); } } It will always produce the following exception because the String is too long for writeUTF: java.io.UTFDataFormatException at java.io.ObjectOutputStream$BlockDataOutputStream.writeUTF(ObjectOutputStream.java:2125) at java.io.ObjectOutputStream$BlockDataOutputStream.writeUTF(ObjectOutputStream.java:1968) at java.io.ObjectOutputStream.writeUTF(ObjectOutputStream.java:841) at ch.qos.logback.classic.WriteUtfTest.testWriteUTF(WriteUtfTest.java:21) Don't worry, I stumbled over this problem in some other project, too. -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 noreply.ceki@qos.ch changed: What |Removed |Added ---------------------------------------------------------------------------- Status|ASSIGNED |RESOLVED Resolution| |FIXED ------- Comment #10 from noreply.ceki@qos.ch 2008-03-13 01:30 -------
The changes in revision 1641 won't really solve the original problem but introduces a whole new one instead.
Why doesn't revision 1641 address the original problem? Thank you for pointing out the string size issue with the writeUTF method in ObjectOutputStream. In revision 1642 the size of the string values in argArray are capped to the exact same limit as allowed by writeUTF. In the mean time, I am marking this bug as fixed. -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 noreply.ceki@qos.ch changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |graham@crazysquirrel.com ------- Comment #11 from noreply.ceki@qos.ch 2008-03-13 01:54 ------- *** Bug 118 has been marked as a duplicate of this bug. *** -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 joern@huxhorn.de changed: What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |REOPENED Resolution|FIXED | ------- Comment #12 from joern@huxhorn.de 2008-03-13 04:00 ------- With "won't really solve the original problem" I meant that the array wouldn't serialize correctly in case of large Strings. And since the bug report says "Serialization of objectArray in LoggingEvent does not always work", and this was still true, it didn't really solve the problem. ;) I should've probably written "but introduces a different one instead" instead of "but introduces a whole new one instead". Sorry if this was confusing. However, I don't think that capping the parameters is acceptable. This is documented nowhere, neither in slf4j (where such a behavior would need to be documented) nor in Logback. I agree that it's probably arguable if log-messages/arguments of log-messages > 0xFFFF characters are reasonable or desirable but this should be up to the user and not the logging framework to decide. It sometimes *is* desirable to dump an xml structure that's larger than 64k and this really isn't absurd in case of log.debug or log.trace. That's why I reopened this bug. I'd also like to know what's wrong with my patch because I really do my best to adhere to your coding style, create minimal impact changes, add tests, etc. - It's less complex because it's using serialization instead of writing the array manually. - Changing the arguments to string is done only once and only if necessary. Serializing an event multiple times will not perform this operation again. - It works for Strings of any size because they are serialized instead of being written using writeUTF. - It creates the formattedMessage lazily if needed, therefore saving time during construction, increasing performance of the whole logging system. - Additionally, formattedMessage should be transient and would be recreated lazily from the message and the arguments after deserialization if needed. I didn't declare formattedMessage transient in my patch because I didn't want to change the serialized structure (which you just did anyway). Instead, I set formattedMessage to null in writeObject which has a comparable effect, i.e. it won't transfer duplicate data that can be derived from already available data (Message + Argument + MessageFormatter) instead. - it's completely transparent for classes using LoggingEvent itself because - the serialized data does not change it's form. - the lazy initialization of formattedMessage is invisible. It's simply not relevant, from the callers perspective, if formattedMessage is initialized in the c'tor or in the getFormattedMessage method. Your change, on the other hand - changes the serialized data without changing the serialVersionUID which produces strange errors while trying to deserialize old events. - creates capped strings if the Strings are to long, which results in the creation of an *additional* String that has a size of 131070 bytes (0xFFFF chars)!! This puts unnecessary burden on the garbage collection and is, in fact, slower than the previous version. - This is done again every time an event is serialized! - By capping the arguments a serialized and deserialized event simply isn't equal to the originally serialized event anymore, which should normally be the case. Is there any place where arguments are used as something else than Strings? I really can't see any other potential problem of my patch... -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 ------- Comment #13 from noreply.ceki@qos.ch 2008-03-13 04:56 ------- Points well taken. I did not wish to transform the arguments in the array to string because (local) filters might perfom processing on the event depending on the values (and type) found in the argument array. This may sound a bit far fetched at this time but I did not want to close this option for the future. Your argument regarding the string size makes sense, although 64K+ strings is not something that will occur often. Anyway, how about if the String was serialized via writeObject instead of writeUTF. More generally, I would like to support the serialization of certain types without conversion to string, for example: - primitive types - Map<String, String> - List<String> WDYT? -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 ------- Comment #14 from noreply.ceki@qos.ch 2008-03-13 17:28 ------- To be more specific, the argumentArray is the only way for a user to pass arguments for a given LoggingEvent instance via the SLF4J API. This may be a very useful feature in the future. -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 ------- Comment #15 from joern@huxhorn.de 2008-03-13 21:52 ------- Yes, using read/writeObject instead of read/writeUTF would solve the acute capping problem. I'm not sure about serializing anything else but String arguments. This would require a not quite easy to implement logic. You'd have to analyze the entire contents of a Collections, probably recusively, in that case because you wouldn't have the generic information anymore... also, the arguments must never be changed in the process. However, I already suggested to change the arguments to String[] instead of Object[] in bug #134 because I originally thought that arguments are only used to format messages (and optionally to extract a Throwable as in my slf4j-suggestion at http://bugzilla.slf4j.org/show_bug.cgi?id=70 ). I just checked out the filtering-related code and realized that it would still be possible to use TurboFilters to perform a decision on the original arguments since TurboFilters are executed before the actual event creation. Because of this, I think it's absolutely viable to change LoggingEvent.argumentArray to String[] and also change the signature of the getter to String[] getArgumentArray() (this method isn't used in the codebase at the moment). I'd suggest to perform the conversion from Object[] to String[] in Logger or, better yet, in some general purpose method in slf4j MessageFormatter (if my slf4j-suggestion is considered, because it would then be necessary to extract the Throwable first and return a Throwable-String[]-formattedString result with message and arguments as params because it would be necessary to at least count placeholders...) so LoggerEvent is freed of some more complexity. This would mean that the c'tor's argArray should also be changed to String[]. It's only called in Logger and test classes so this change should be easy. This would effectively remove the reason to change the old serialization code at all. The whole reason for this bug would vanish. (I'd still suggest to set formattedMessage transient and initialize it lazily.) I do have some general concerns about either TurboFilter or Filter working directly with arguments, though. They currently both have the ability to interact with application-level objects! This would, of course, be an error in the respective Filter but it doesn't make me feel very well about it at all. Those objects probably want to execute some logging events, too, which could lead to some nasty side effects, I fear. Probably even a deadlock. Therefore I'd even suggest to remove params[] from the TurboFilter.decide signature to remove the risk of side-effects caused by log statements. This would mean that application-level objects are only touched by Logger which can be expected to be safe. -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 ------- Comment #16 from joern@huxhorn.de 2008-03-13 23:07 ------- Created an attachment (id=25) --> (http://bugzilla.qos.ch/attachment.cgi?id=25&action=view) Changed args to String[] and lazy formattedMessage This patch does only change the LoggingEvent arguments to String[]. It does *not* implement my suggested changes to TurboFilter! -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 noreply.ceki@qos.ch changed: What |Removed |Added ---------------------------------------------------------------------------- Status|REOPENED |RESOLVED Resolution| |REMIND ------- Comment #17 from noreply.ceki@qos.ch 2008-03-19 19:01 -------
This would require a not quite easy to implement logic. You'd have to analyze the entire contents of a Collections, probably recusively, in that case because you wouldn't have the generic information anymore... also, the arguments must never be changed in the process.
Very good point. However, there are way to constrain the problem to a more manageable issue. Assume logback is used in a large and complicated business process and we would like to track messages that are treated over several applications distributed over many machines. It would be interesting to specify parameters such as e.g. server id, application name, request id, transaction id, user id etc. The last three parameters are specific to the request being processed and presumably should be specified in the logging event as parameters. I would argue that passing those parameters in an object of type Map<String, String> makes sense. Assuming a class called LogbackEventMap which extends HashMap<String, String>, we could simplify the problem by serializing objects of type String or LogbackEventMap. This allows for flexibility without introducing much new complexity.
However, I already suggested to change the arguments to String[] instead of Object[] in bug #134 because I originally thought that arguments are only used to format messages (and optionally to extract a Throwable as in my slf4j-suggestion at http://bugzilla.slf4j.org/show_bug.cgi?id=70 ).
Well, arguments could also be used as an extension mechanism to LoggingEvent via SLF4J's API. Apart from the MDC, that's the only extension point available using the SLF4J "standard".
I just checked out the filtering-related code and realized that it would still be possible to use TurboFilters to perform a decision on the original arguments since TurboFilters are executed before the actual event creation.
I had not thought of TurboFilters. As such, it should not come as a surprise if I say that TurboFilters were not on my mind when we previously discussed the type of LoggingEvent.argumentArray.
Because of this, I think it's absolutely viable to change LoggingEvent.argumentArray to String[] and also change the signature of the getter to String[] getArgumentArray() (this method isn't used in the codebase at the moment). I'd suggest to perform the conversion from Object[] to String[] in Logger or, better yet, in some general purpose method in slf4j MessageFormatter (if my slf4j-suggestion is considered, because it would then be necessary to extract the Throwable first and return a Throwable-String[]-formattedString result with message and arguments as params because it would be necessary to at least count placeholders...) so LoggerEvent is freed of some more complexity. This would mean that the c'tor's argArray should also be changed to String[]. It's only called in Logger and test classes so this change should be easy.
At this juncture, I would like to hold on to the idea there is some purpose to keeping the type of LoggingEvent.argumentArray as Object[]. The future may prove that the idea was merely sepeculative generality. Time will tell.
I do have some general concerns about either TurboFilter or Filter working directly with arguments, though. They currently both have the ability to interact with application-level objects! This would, of course, be an error in the respective Filter but it doesn't make me feel very well about it at all. Those objects probably want to execute some logging events, too, which could lead to some nasty side effects, I fear. Probably even a deadlock.
Therefore I'd even suggest to remove params[] from the TurboFilter.decide signature to remove the risk of side-effects caused by log statements. This would mean that application-level objects are only touched by Logger which can be expected to be safe.
Those are all valid arguments assuming that LoggingEvent.argumentArray is intended only message formatting. However, as I tried to argument above, argumentArray can also be seen as a data mule extending the fields available in LoggingEvent. I would like to come to this issue in a few month after it has matured a bit more. -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 ------- Comment #18 from joern@huxhorn.de 2008-03-20 18:01 ------- I'm fine with the writeObject fix of this specific problem. I still think that it would be a bad idea to use arguments beyond message formatting because it reduces the stability of the logging framework (as I explained above) and would also be undocumented behavior based on the slf4j api. It would mean that other implementations of slf4j would definitely behave differently compared to logback, which shouldn't be the case, IMHO. So any additional behavior should probably also be done in slf4j (as is the case with message formatting right now) so all implementations have the chance to implement a similar functionality (like my Throwable suggestion at http://bugzilla.slf4j.org/show_bug.cgi?id=70 - all implementations could use that additional feature). I hope I don't annoy you with my persistence... -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
http://bugzilla.qos.ch/show_bug.cgi?id=100 ------- Comment #19 from noreply.ceki@qos.ch 2008-03-22 19:32 ------- While it is true that logging behavior would depend on the underlying logging system, the changes we are talking about are in the logback API and only in the logback API. So if the user wishes to track a message processed over several applications distributed over many machines. It would be interesting for her to specify parameters such as e.g. server id, application name, request id, transaction id, user id etc. The last three parameters are specific to the request being processed and presumably should be specified in the logging event as parameters. It could look as follows: LogbackEventMap lem = new LogbackEventMap(); lem.put("transactionId", getTransactionId()); lem.put("serverId", getServerId()); lem.put("requestId", getRequestId()); lem.put("userId", getUserId()); org.slf4j.Logger logger = LoggerFactory.getLogger("..."); logger.debug("Started processing message", lem); The first 5 lines are logback specific while the last 2 lines are just the SLF4J API. We are taking advantage of a detail in logback's implementation of the SLF4J API (which is by the way the subject of this bug). Thus, logback's implementation of SLF4J logger will carry on the argumentArray as is. Under certain strict restrictions, the argument array may even survive serialization unmodified. Assuming the use case I describe here is not that interesting, then I think your line of thought is very valid. It brings interesting simplifications. However, I am inclined to think that the use case is an important one, and worth tying application code to logback's implementation. Again, no one is forced to take advantage of enhancements in logback's implementation of SLF4J's Logger interface. Moreover, the Logger interface was not modified in any way. In any case, many thanks for bearing with me on this issue. I definitely appreciate it. Given that bugs corrected in the trunk are being reported as duplicates of previous bug reports, I wish to cut a new release some time next week. -- Configure bugmail: http://bugzilla.qos.ch/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
participants (1)
-
bugzilla-daemon＠pixie.qos.ch