Bug 60199 - Improve error message if a session attribute could not load due to deserialization problems
Summary: Improve error message if a session attribute could not load due to deserializ...
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 8
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 8.0.37
Hardware: PC All
: P2 normal (vote)
Target Milestone: ----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-10-04 09:27 UTC by igor.mukhin
Modified: 2016-10-06 08:14 UTC (History)
0 users



Attachments
Proposed a patch for 8.0.x (2.11 KB, patch)
2016-10-04 19:52 UTC, igor.mukhin
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description igor.mukhin 2016-10-04 09:27:33 UTC
Again and again I find myself in searching for classes that do not implement Serializable interface but are set into session. When you have such a class you just see in the log at tomcat start that there was a problem while deserializing the session object. I would be very helpful if the log would say which attribute have caused the problem.

Sample implementation StandardSession.java in doReadObject(ObjectInputStream stream):

Instead of:

        for (int i = 0; i < n; i++) {
            String name = (String) stream.readObject();
            Object value = stream.readObject();
            if ((value instanceof String) && (value.equals(NOT_SERIALIZED)))
                continue;
            if (manager.getContext().getLogger().isDebugEnabled())
                manager.getContext().getLogger().debug("  loading attribute '" + name +
                    "' with value '" + value + "'");
            attributes.put(name, value);
        }

do:


        for (int i = 0; i < n; i++) {
            String name = (String) stream.readObject();

            Object value = null;
            try {
                value = stream.readObject();
            } catch (Exception e) {
                manager.getContext().getLogger().error(String.format("Attribute %s could not be deserialized due to %s", name, e.getMessage()));
            }

            if ((value instanceof String) && (value.equals(NOT_SERIALIZED)))
                continue;

            if (manager.getContext().getLogger().isDebugEnabled())
                manager.getContext().getLogger().debug("  loading attribute '" + name +
                    "' with value '" + value + "'");
            attributes.put(name, value);
        }
Comment 1 Christopher Schultz 2016-10-04 17:00:13 UTC
Care to prepare a formal patch?
Comment 2 igor.mukhin 2016-10-04 19:52:52 UTC
Created attachment 34324 [details]
Proposed a patch for 8.0.x

Added a patch
Comment 3 Mark Thomas 2016-10-05 11:34:18 UTC
I'm not completely against this but...

The error is logged, with the attribute name when writing the session to disk. Why do you need another error message when reading it?
Comment 4 igor.mukhin 2016-10-06 07:26:48 UTC
I never saw such a warning on the tomcat shutdown. And I just tested it, and I don't any warning still.

But I see the line you meant in the code of StandardSession.doWriteObject:

manager.getContext().getLogger().warn(                     sm.getString("standardSession.notSerializable", saveNames.get(i), id), e);

In the debugger I see the line executed not I don't see any output in my logs. Really strange. (This is a Spring Boot project with devtools)

Still I think telling the name of the attribute which caused the problem on the tomcat start would be helpful, because one would know right away what the problem is, and he does not need to know that there was a message in the shutdown log which nobody every reads.
Comment 5 Mark Thomas 2016-10-06 08:09:09 UTC
With the proposed patch the error is logged higher up the stack. I suspect a logging configuration issue. The users list is the place to seek help with that.

The proposed patch also causes deserialization to stop on the first error. That is not the desired behaviour.

I have an alternative patch that I'll apply shortly that logs a warn message with the attribute name or a debug message that includes the stack trace.
Comment 6 igor.mukhin 2016-10-06 08:11:55 UTC
Mark, great! Thank you.
Comment 7 Mark Thomas 2016-10-06 08:14:27 UTC
This has been fixed in the following branches:
- 9.0.x for 9.0.0.M11 onwards
- 8.5.x for 8.5.6 onwards
- 8.0.x for 8.0.38 onwards
- 7.0.x for 7.0.73 onwards