Bug 44109 - Telnet Appender throws null pointers at log time when socket couldn't be opened
Telnet Appender throws null pointers at log time when socket couldn't be opened
Status: RESOLVED FIXED
Product: Log4j
Classification: Unclassified
Component: Appender
1.2
Other other
: P2 normal
: ---
Assigned To: log4j-dev
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2007-12-19 14:25 UTC by Dan Armbrust
Modified: 2008-01-18 07:25 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Dan Armbrust 2007-12-19 14:25:00 UTC
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.
Comment 1 Curt Arnold 2008-01-17 10:20:56 UTC
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.
Comment 2 Dan Armbrust 2008-01-17 11:06:15 UTC
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.

Comment 3 Curt Arnold 2008-01-17 13:52:08 UTC
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.
Comment 4 Dan Armbrust 2008-01-18 07:25:45 UTC
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.