| Summary: | Telnet Appender throws null pointers at log time when socket couldn't be opened | ||
|---|---|---|---|
| Product: | Log4j - Now in Jira | Reporter: | Dan Armbrust <daniel.armbrust.list> |
| Component: | Appender | Assignee: | log4j-dev <log4j-dev> |
| Status: | RESOLVED FIXED | ||
| Severity: | normal | ||
| Priority: | P2 | ||
| Version: | 1.2 | ||
| Target Milestone: | --- | ||
| Hardware: | Other | ||
| OS: | other | ||
One of the design goals of log4j 2.0 is to provide feedback of unexpected conditions. Basically log4j 1.x's design was to hide all feedback on the health of the logging system from the application developer and what feedback was provided was sent to the console. The null pointer in TelnetAppender.append however should have been checked, committed in rev 612911 and 612914. I'm not sure where you put the null check - Just to be clear - I think that the null check needs to be in the class above the TelnetAppender - not in the TelnetAppender itself. The append() sequence should never throw an error that it caused (for whatever reason) back out to the app that was just trying to log a message. So, no matter how poor of an Appender I create, if it messes up and takes a runtime exception, that shouldn't bubble back out to the caller. Second, and I should have opened another bug on this, is the issue of creating the SocketAppender and finding out about errors where the port couldn't be opened. I fixed this by making the TelnetAppender constructor take in a port number, and run the code that is currently run in activateOptions. This way, the constructor can throw the port in use exception back to the caller. I removed the setPort method, and made the activate options method do nothing. I can post the full TelnetAppender class, if you like, which fixes this startup issue, and bug 44108. I added a check for null at the head of TelnetAppender.append in rev 612911, to see just that change use svn diff like: svn diff -r 612910:612911 I'd appreciate your feedback on the recently checked in code. I did look at the code in the comments of 44108, but could not use it due to the JDK 1.5 stuff. The rework to have a single collection is good, but it was a lot simpler to add the sync blocks and they needed them anyway even if there was just one collection. There are two more global issues that you have mentioned: the lack of programmatic feedback on configuration or start up issues the lack of a try/catch/finally block in Categories.callAppenders or the like to catch unexpected exceptions during logging. The lack of programmatic feedback is a log4j 2.0 issue. log4j 1.2 made its design decisions 6 or so years ago and we are generally stuck with them for maintenance releases. The lack of a try/catch/finally block the Logger level was also made at that same time. Adding it now would affect the performance of every log4j user, not just those who were using TelnetAppender, Not that it would be a bad idea, but it is less likely to have serious unexpected consequences to make a isolated local change than a global change. I can certainly see your point - I was surprised when I had the null pointer exception bubble out - all the time I have been using log4j, I've never had it happen before - so its probably a good performance tradeoff. But at the same time, it nags me as wrong that any poorly written logger could inject runtime exceptions into the code simply calling a log method. Certainly no issue with making it a 2.0 issue, given the potential issues with the change. In my case, I have to have programmatic feedback if the telnet appender can't be started due to port issues, so I'll just stick with my modified constructor solution for now. It seems to me that a correct fix for a 2.0 release would be to make the activateOptions method throw a checked exception. |
The Telnet Appender seems to have a poorly designed start up sequence. Here is the activateOptions method: /** all of the options have been set, create the socket handler and wait for connections. */ public void activateOptions() { try { sh = new SocketHandler(port); sh.start(); } catch(Exception e) { e.printStackTrace(); } super.activateOptions(); } If the socket handler fails to open the socket - say for instance - the port is already in use - it will nearly silently eat the error - leaving itself unconfigured. If someone is trying to create a socket appender programatically, they have no way of knowing if the activate step was successful or not. I'm not sure how to fix this, since the AppenderSkeleton interface does not allow the activateOptions method to throw exceptions. Perhaps there should be a new constructor that would take in all the options, do the work of the activateOptions method, and throw the proper exceptions. Or a getError() method, or something. Worse - if the activateOptions() method fails, it leaves the sh variable null. Look at what happens next: /** Handles a log event. For this appender, that means writing the message to each connected client. */ protected void append(LoggingEvent event) { sh.send(this.layout.format(event)); Hello, null pointer! At log time, no less. That code definitely needs a null check. Having a mis-configured appender shouldn't toss null pointers into the logging sequence.