Bug 50238

Summary: wrong log levels logged with the serialized LoggingEvent
Product: Log4j - Now in Jira Reporter: Masaru San <sasakij>
Component: AppenderAssignee: log4j-dev <log4j-dev>
Status: NEW ---    
Severity: critical    
Priority: P2    
Version: 1.2   
Target Milestone: ---   
Hardware: All   
OS: All   

Description Masaru San 2010-11-09 04:02:50 UTC
This occurs under logging with serialized LoggerEvent as 
SimpleSocketServe does.

For example 

Multi processed socket clients send logs to SocketServer, and server 
reads serialized LoggingEvents with o.a.l.s.LoggingEvent#readObject(), 
this calls internally o.a.l.s.LoggingEvent#readLevel(ObjectInputStream) 
which uses thead-unsafe `static final` variable. (see below at line 439)

This results in inconsistent log levels.


I reproduced with 4-processes socket clients, each client has 10-threads, 
toward single-process SimpleSocketServer. Clients sent 80,000 logs in 
all, and about 10 of them were wrong leveled.

[LoggingEvent.java]

142:  static final Integer[] PARAM_ARRAY = new Integer[1];

...

417:  private
418:  void readLevel(ObjectInputStream ois)
419:                      throws java.io.IOException, ClassNotFoundException {
420:
421:    int p = ois.readInt();
422:    try {
423:      String className = (String) ois.readObject();
424:      if(className == null) {
425:        level = Level.toLevel(p);
426:      } else {
427:        Method m = (Method) methodCache.get(className);
428:        if(m == null) {
429:          Class clazz = Loader.loadClass(className);
430:          // Note that we use Class.getDeclaredMethod instead of
431:          // Class.getMethod. This assumes that the Level subclass
432:          // implements the toLevel(int) method which is a
433:          // requirement. Actually, it does not make sense for Level
434:          // subclasses NOT to implement this method. Also note that
435:          // only Level can be subclassed and not Priority.
436:          m = clazz.getDeclaredMethod(TO_LEVEL, TO_LEVEL_PARAMS);
437:          methodCache.put(className, m);
438:        }
439:        PARAM_ARRAY[0] = new Integer(p);  // <=== !!! thread-unsafe !!!
440:        level = (Level) m.invoke(null,  PARAM_ARRAY);
441:      }
442:    } catch(InvocationTargetException e) {
443:        if (e.getTargetException() instanceof InterruptedException
444:                || e.getTargetException() instanceof InterruptedIOException) {
445:            Thread.currentThread().interrupt();
446:        }
447:    LogLog.warn("Level deserialization failed, reverting to default.", e);
448:        level = Level.toLevel(p);
449:    } catch(NoSuchMethodException e) {
450:        LogLog.warn("Level deserialization failed, reverting to default.", e);
451:        level = Level.toLevel(p);
452:    } catch(IllegalAccessException e) {
453:        LogLog.warn("Level deserialization failed, reverting to default.", e);
454:        level = Level.toLevel(p);
455:    } catch(RuntimeException e) {
456:        LogLog.warn("Level deserialization failed, reverting to default.", e);
457:        level = Level.toLevel(p);
458:    }
459:  }
Comment 1 Curt Arnold 2010-11-12 22:02:38 UTC
Fix applied in rev 1034632.

Could you confirm that you were using custom log levels?  From my reading that could would only be reached in that case.  If you are reaching that code without using custom levels, then we should investigate why since it would appear to add a lot of unnecessary reflection.
Comment 2 Masaru San 2010-11-18 10:33:02 UTC
Yes, I'm using custom log levels.
Thanks a lot for your help.
Comment 3 Masaru San 2010-11-24 23:57:06 UTC
I'm sorry, i've forgotten to change status.