1 / 47

06:05:55 07.11.2011 INFO (Class1.java:41) User ‘ bfernan ’ Start method1

06:05:55 07.11.2011 INFO (Class1.java:41) User ‘ bfernan ’ Start method1 06:05:55 07.11.2011 INFO (Class1.java:44) Before retrieve information from DB 06:05:55 07.11.2011 INFO (Class1.java:46) After retrieve information from DB 06:05:55 07.11.2011 INFO (Class1.java:50) Updating information

more
Télécharger la présentation

06:05:55 07.11.2011 INFO (Class1.java:41) User ‘ bfernan ’ Start method1

An Image/Link below is provided (as is) to download presentation Download Policy: Content on the Website is provided to you AS IS for your information and personal use and may not be sold / licensed / shared on other websites without getting consent from its author. Content is provided to you AS IS for your information and personal use only. Download presentation by click this link. While downloading, if for some reason you are not able to download a presentation, the publisher may have deleted the file from their server. During download, if you can't get a presentation, the file might be deleted by the publisher.

E N D

Presentation Transcript

  1. 06:05:55 07.11.2011 INFO (Class1.java:41) User ‘bfernan’ Start method1 06:05:55 07.11.2011 INFO (Class1.java:44) Before retrieve information from DB 06:05:55 07.11.2011 INFO (Class1.java:46) After retrieve information from DB 06:05:55 07.11.2011 INFO (Class1.java:50) Updating information 06:05:55 07.11.2011 INFO (Class1.java:94) Before save information in the DB 06:05:56 07.11.2011 INFO (Class1.java:96) After retrieve information in the DB 06:05:56 07.11.2011 INFO (Class1.java:100) User ‘bfernan’ Finish method1 06:05:56 07.11.2011 INFO (Class1.java:211) User ‘xxxxxxx’ Start method2 06:05:56 07.11.2011 INFO (Class1.java:220) Before retrieve information from DB 06:05:56 07.11.2011 INFO (Class1.java:243) Error retrieving information from DB: NullPointerException java.lang.NullPointerException at pkg.Class1.method2(Class1.java:225) at pkg.Class1.methodN(Class1.java:458) at pkg2.ClassZ.methodUpdate(ClassZ.java:458) at … at java.lang.Thread.run(Thread.java:595) 06:05:57 07.11.2011 INFO (Class1.java:41) User ‘bfernan’ Start method1 06:05:57 07.11.2011 INFO (Class1.java:44) Before retrieve information from DB 06:05:57 07.11.2011 INFO (Class1.java:46) After retrieve information from DB 06:05:57 07.11.2011 INFO (Class1.java:50) Updating information 06:05:57 07.11.2011 INFO (Class1.java:94) Before save information in the DB 06:05:58 07.11.2011 INFO (Class1.java:96) After retrieve information in the DB 06:05:58 07.11.2011 INFO (Class1.java:100) User ‘bfernan’ Finish method1 06:05:58 07.11.2011 INFO (Class1.java:41) User ‘bfernan’ Start method1 06:05:58 07.11.2011 INFO (Class1.java:44) Before retrieve information from DB 06:05:58 07.11.2011 INFO (Class1.java:46) After retrieve information from DB 06:05:59 07.11.2011 INFO (Class1.java:50) Updating information 06:05:59 07.11.2011 INFO (Class1.java:94) Before save information in the DB 06:05:59 07.11.2011 INFO (Class1.java:96) After retrieve information in the DB 06:05:59 07.11.2011 INFO (Class1.java:100) User ‘bfernan’ Finish method1 Logging Best Practices Dubna 2012 Benedicto Fernandez Software Engineer CERN / GS-AIS

  2. Only useful for debugging/development?

  3. Contents • Logging libraries • Logging levels • Where to log? • Performance • How to access? • What to log?

  4. What are we talking about?

  5. First Logging: System.out.println • Easy • Quick • No dependencies • Redirect to file or null in Production • Log everything or nothing System.out.println(“Start method1”);

  6. Example Start method1 Before retrieve information from DB After retrieve information from DB Updating information Before save information in the DB After save information in the DB Finish method1 Start method2 Before retrieve information from DB Error retrieving information from DB: NullPointerException

  7. Next evolution:Logging Libraries • Log4j, Java Logging… log.info(“Start method1”); • Provide • Time of the message • The class, the method, the line • … • Print easily the stacktrace • Log to files, databases, system log mechanisms

  8. Example 06:05:56 07.11.2011 INFO (Class1.java:211) Start method2 06:05:56 07.11.2011 INFO (Class1.java:220) Before retrieve information from DB 06:05:56 07.11.2011 INFO (Class1.java:243) Error retrieving information from DB: NullPointerException java.lang.NullPointerException at pkg.Class1.method2(Class1.java:225) at pkg.Class1.methodN(Class1.java:458) at pkg2.ClassZ.methodUpdate(ClassZ.java:458) at … at java.lang.Thread.run(Thread.java:595)

  9. Example 06:05:56 07.11.2011INFO (Class1.java:211) Start method2 06:05:56 07.11.2011 INFO (Class1.java:220) Before retrieve information from DB 06:05:56 07.11.2011 INFO (Class1.java:243) Error retrieving information from DB: NullPointerException java.lang.NullPointerException at pkg.Class1.method2(Class1.java:225) at pkg.Class1.methodN(Class1.java:458) at pkg2.ClassZ.methodUpdate(ClassZ.java:458) at … at java.lang.Thread.run(Thread.java:595)

  10. Example 06:05:56 07.11.2011 INFO (Class1.java:211) Start method2 06:05:56 07.11.2011 INFO (Class1.java:220) Before retrieve information from DB 06:05:56 07.11.2011 INFO (Class1.java:243) Error retrieving information from DB: NullPointerException java.lang.NullPointerException at pkg.Class1.method2(Class1.java:225) at pkg.Class1.methodN(Class1.java:458) at pkg2.ClassZ.methodUpdate(ClassZ.java:458) at … at java.lang.Thread.run(Thread.java:595)

  11. Example 06:05:56 07.11.2011 INFO (Class1.java:211) Start method2 06:05:56 07.11.2011 INFO (Class1.java:220) Before retrieve information from DB 06:05:56 07.11.2011 INFO (Class1.java:243) Error retrieving information from DB: NullPointerException java.lang.NullPointerException at pkg.Class1.method2(Class1.java:225) at pkg.Class1.methodN(Class1.java:458) at pkg2.ClassZ.methodUpdate(ClassZ.java:458) at … at java.lang.Thread.run(Thread.java:595)

  12. Logging levels (I) • Log4j • Trace • Debug • Info • Warning • Error • Fatal • Java Logging • Finest • Finer • Fine • Config • Info • Warning • Severe

  13. Example 06:05:56 07.11.2011 INFO (Class1.java:211) Start method2 06:05:56 07.11.2011 INFO (Class1.java:211) Parameter ‘age’ is not an Integer 06:05:56 07.11.2011 INFO (Class1.java:211) Finish method2 06:05:56 07.11.2011 INFO (Class1.java:211) Start method2 06:05:56 07.11.2011 DEBUG (Class1.java:220) Before retrieve information from DB 06:05:56 07.11.2011 ERROR (Class1.java:243) Error retrieving information from DB: NullPointerException java.lang.NullPointerException at pkg.Class1.method2(Class1.java:225) at pkg.Class1.methodN(Class1.java:458) at pkg2.ClassZ.methodUpdate(ClassZ.java:458) at … at java.lang.Thread.run(Thread.java:595)

  14. Example 06:05:56 07.11.2011 INFO (Class1.java:211) Start method2 06:05:56 07.11.2011 INFO (Class1.java:211) Parameter ‘age’ is not an Integer 06:05:56 07.11.2011 INFO (Class1.java:211) Finish method2 06:05:56 07.11.2011 INFO (Class1.java:211) Start method2 06:05:56 07.11.2011 DEBUG (Class1.java:220) Before retrieve information from DB 06:05:56 07.11.2011 ERROR (Class1.java:243) Error retrieving information from DB: NullPointerException java.lang.NullPointerException at pkg.Class1.method2(Class1.java:225) at pkg.Class1.methodN(Class1.java:458) at pkg2.ClassZ.methodUpdate(ClassZ.java:458) at … at java.lang.Thread.run(Thread.java:595)

  15. Example 06:05:56 07.11.2011 INFO (Class1.java:211) Start method2 06:05:56 07.11.2011 INFO (Class1.java:211) Parameter ‘age’ is not an Integer 06:05:56 07.11.2011 INFO (Class1.java:211) Finish method2 06:05:56 07.11.2011 INFO (Class1.java:211) Start method2 06:05:56 07.11.2011 DEBUG (Class1.java:220) Before retrieve information from DB 06:05:56 07.11.2011 ERROR (Class1.java:243) Error retrieving information from DB: NullPointerException java.lang.NullPointerException at pkg.Class1.method2(Class1.java:225) at pkg.Class1.methodN(Class1.java:458) at pkg2.ClassZ.methodUpdate(ClassZ.java:458) at … at java.lang.Thread.run(Thread.java:595)

  16. Logging levels (II) log4j.logger.ch.cern.ais=DEBUG log4j.logger.ch.cern.ais.package.Class1=TRACE log4j.logger.org.springframework=ERROR log4j.logger.org.springframework.ws=INFO

  17. Where to log? • Text files (Plain text, XML,…) • Binary files • Database • Syslog (Windows & Unix/Linux) • Network (TCP & UDP)

  18. Where to log? Text files (Plain text, XML,…) Binary files Database Syslog (Windows & Unix/Linux) Network (TCP & UDP) Always to a Text file (+ something else)?

  19. Performance • "hidden" cost of parameter construction logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));

  20. Performance "hidden" cost of parameter construction logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i])); Solution if (logger.isDebugEnabled()) { logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i])); }

  21. Next evolution:Logging Libraries v2.0 • Simple Logging Facade (SLF4J) • Logback • Parameterized messages logger.debug("Entry number: {} is {}“, i , String.valueOf(entry[i]));

  22. Multiple users (I) • Different users working simultaneously • Log messages mixed for different users • Difficult to trace user’s actions

  23. Multiple users (I) • Different users working simultaneously • Log messages mixed for different users • Difficult to trace user’s actions • Log User ID

  24. Multiple users - Example 06:05:55 07.11.2011 INFO (Class1.java:41) User=bfernan; message=‘Start method1’; 06:05:55 07.11.2011 DEBUG (Class1.java:44) message=‘Before retrieve information from DB’; 06:05:55 07.11.2011 DEBUG (Class1.java:46) message=‘After retrieve information from DB’; 06:05:55 07.11.2011 INFO (Class1.java:50) message=‘Updating information’; 06:05:55 07.11.2011 DEBUG (Class1.java:94) message=‘Before save information in the DB’; 06:05:56 07.11.2011 DEBUG (Class1.java:96) message=‘After save information in the DB’; 06:05:56 07.11.2011 INFO (Class1.java:100) User=bfernan; message=‘Finish method1’; 06:05:56 07.11.2011 INFO (Class1.java:211) User=xxxxxxx; message=‘Start method2’; 06:05:56 07.11.2011 DEBUG (Class1.java:220) message=‘Before retrieve information from DB’; 06:05:56 07.11.2011 ERROR (Class1.java:243) message=‘Error retrieving information from DB: NullPointerException’;

  25. Multiple users (II) • Mapped Diagnostic Contexts (MDC) public void serviceMethod1(String userName,…) { String userName = getLoggedUserName(); MDC.put( “userName”, userName); } • Configuration …PatternLayout=%T User=%X{userName};message=‘%m’;%n

  26. Multiple users (III) public void doFilter(ServletRequest request, ServletResponse response,    FilterChain chain) throws IOException, ServletException {    HttpServletRequest req = (HttpServletRequest) request;        Principal principal = req.getUserPrincipal();// Please note that we could have also used a cookie to     // retrieve the user nameif (principal != null) {      String username = principal.getName();      MDC.put(USER_KEY, username);    } try {      chain.doFilter(request, response);    } finally {      MDC.remove(USER_KEY);    }  }

  27. Multiple users (III) public void doFilter(ServletRequest request, ServletResponse response,    FilterChain chain) throws IOException, ServletException {    HttpServletRequest req = (HttpServletRequest) request;        Principal principal = req.getUserPrincipal();    // Please note that we could have also used a cookie to     // retrieve the user name    if (principal != null) {      String username = principal.getName();MDC.put(USER_KEY, username);}     try {      chain.doFilter(request, response);    } finally {MDC.remove(USER_KEY);}  }

  28. Multiple users - Example 06:05:55 07.11.2011 INFO (Class1.java:41) User=bfernan; message=‘Start method1’; 06:05:55 07.11.2011 DEBUG (Class1.java:44) User=bfernan; message=‘Before retrieve information from DB’; 06:05:55 07.11.2011 DEBUG (Class1.java:46) User=bfernan; message=‘After retrieve information from DB’; 06:05:55 07.11.2011 INFO (Class1.java:50) User=bfernan; message=‘Updating information’; 06:05:55 07.11.2011 DEBUG (Class1.java:94) User=bfernan; message=‘Before save information in the DB’; 06:05:56 07.11.2011 DEBUG (Class1.java:96) User=bfernan; message=‘After retrieve information in the DB’; 06:05:56 07.11.2011 INFO (Class1.java:100) User=bfernan; message=‘Finish method1’; 06:05:56 07.11.2011 INFO (Class1.java:211) User=xxxxxxx; message=‘Start method2’; 06:05:56 07.11.2011 DEBUG (Class1.java:220) User=xxxxxxx; message=‘Before retrieve information from DB’; 06:05:56 07.11.2011 ERROR (Class1.java:243) User=xxxxxxx; message=‘Error retrieving information from DB: NullPointerException’;

  29. Multiple Connections Same User (I) • “Account” shared by 2+ end users • Different • Session ID • Remote Address user1

  30. Multiple Connections Same User (I) “Account” shared by 2+ end users Different Session ID Remote Address Log Session ID Log Remote IP user1

  31. Multiple Connections Same User (I) - Example 06:05:55 07.11.2011 INFO (Class1.java:41) IP=192.168.2.99;Session=00000001; User=bfernan;message=‘Start method1’; 06:05:55 07.11.2011 DEBUG (Class1.java:44) IP=192.168.2.99;Session=00000001; User=bfernan;message=‘Before retrieve information from DB’; 06:05:55 07.11.2011 INFO (Class1.java:211) IP=61.82.23.9;Session=00000002; User=bfernan;message=‘Start method2’; 06:05:55 07.11.2011 DEBUG (Class1.java:220) IP=61.82.23.9;Session=00000002; User=bfernan;message=‘Before retrieve information from DB’; 06:05:55 07.11.2011 DEBUG (Class1.java:46) IP=192.168.2.99;Session=00000001; User=bfernan;message=‘After retrieve information from DB’; 06:05:55 07.11.2011 INFO (Class1.java:50) IP=192.168.2.99;Session=00000001; User=bfernan;message=‘Updating information’; 06:05:56 07.11.2011 DEBUG (Class1.java:94) IP=192.168.2.99;Session=00000001; User=bfernan;message=‘Before save information in the DB’; 06:05:56 07.11.2011 DEBUG (Class1.java:96) IP=192.168.2.99;Session=00000001; User=bfernan;message=‘After retrieve information in the DB’; 06:05:56 07.11.2011 ERROR (Class1.java:243) IP=61.82.23.9;Session=00000002; User=bfernan;message=‘Error retrieving information from DB: NullPointerException’; 06:05:56 07.11.2011 INFO (Class1.java:100) IP=192.168.2.99;Session=00000001;User=bfernan;message=‘Finish method1’;

  32. Multiple Connections Same User (II) • What about tabs? • Same Remote IP • Same Session ID

  33. Multiple Connections Same User (II) What about tabs? Same Remote IP Same Session ID Log Transaction ID

  34. Multiple Connections Same User (I) - Example 06:05:55 07.11.2011 INFO (Class1.java:41) IP=192.168.2.99;Session=00000001; Transaction=00000001;User=bfernan;message=‘Start method1’; 06:05:55 07.11.2011 DEBUG (Class1.java:44) IP=192.168.2.99;Session=00000001; Transaction=00000001;User=bfernan;message=‘Before retrieve information from DB’; 06:05:55 07.11.2011 INFO (Class1.java:211) IP=192.168.2.99;Session=00000001; Transaction=00000002;User=bfernan;message=‘Start method2’; 06:05:55 07.11.2011 DEBUG (Class1.java:220) IP=192.168.2.99;Session=00000001; Transaction=00000002;User=bfernan;message=‘Before retrieve information from DB’; 06:05:55 07.11.2011 DEBUG (Class1.java:46) IP=192.168.2.99;Session=00000001; Transaction=00000001;User=bfernan;message=‘After retrieve information from DB’; 06:05:55 07.11.2011 INFO (Class1.java:50) IP=192.168.2.99;Session=00000001; Transaction=00000001;User=bfernan;message=‘Updating information’; 06:05:56 07.11.2011 DEBUG (Class1.java:94) IP=192.168.2.99;Session=00000001; Transaction=00000001;User=bfernan;message=‘Before save information in the DB’; 06:05:56 07.11.2011 DEBUG (Class1.java:96) IP=192.168.2.99;Session=00000001; Transaction=00000001;User=bfernan;message=‘After retrieve information in the DB’; 06:05:56 07.11.2011 ERROR (Class1.java:243) IP=192.168.2.99;Session=00000001; Transaction=00000002;User=bfernan;message=‘Error retrieving information from DB: NullPointerException’; 06:05:56 07.11.2011 INFO (Class1.java:100) IP=192.168.2.99;Session=00000001; Transaction=00000001;User=bfernan;message=‘Finish method1’;

  35. How to access the information? v1.0 View the file Human readable format System utils (grep command) $ grep '.*ERROR.* User bfernan .*' log_cra-ws.log Easy for regext (Ex: key=value;) $ grep ‘.*ERROR.*;User=bfernan;.*’ log_cra-ws.log

  36. Cluster of Servers • Application distributed several Servers • 1 log file for each server Which one contains the error?

  37. How to access the information? v2.0 Forward log messages to a Server Log4j Server UI Tools Apache Log4j Chainsaw MindTree Insight

  38. Analytic Tools • Splunk • Indexer • Search Engine • “Pseudo” real-time • Alerts

  39. Example

  40. Example

  41. Example

  42. What to log? • User requests (start & end) • Service methods calls (start & end) • Calls to external systems ( before & after) • Errors • Any relevant state

  43. Conclusions (I) • Log everything useful, not only debug information • Log to text files, human readable format • Use a template parseable with regexp (Ex: key=value;)

  44. Conclusions (II) • Use the appropriate level • One single action per line • Be careful with the performance • Be ready to profit of it

  45. Why not logging standards?

  46. “A good job can save a day of work”

  47. 06:05:55 07.11.2011 INFO (Class1.java:41) User ‘bfernan’ Start method1 06:05:55 07.11.2011 INFO (Class1.java:44) Before retrieve information from DB 06:05:55 07.11.2011 INFO (Class1.java:46) After retrieve information from DB 06:05:55 07.11.2011 INFO (Class1.java:50) Updating information 06:05:55 07.11.2011 INFO (Class1.java:94) Before save information in the DB 06:05:56 07.11.2011 INFO (Class1.java:96) After retrieve information in the DB 06:05:56 07.11.2011 INFO (Class1.java:100) User ‘bfernan’ Finish method1 06:05:56 07.11.2011 INFO (Class1.java:211) User ‘xxxxxxx’ Start method2 06:05:56 07.11.2011 INFO (Class1.java:220) Before retrieve information from DB 06:05:56 07.11.2011 INFO (Class1.java:243) Error retrieving information from DB: NullPointerException java.lang.NullPointerException at pkg.Class1.method2(Class1.java:225) at pkg.Class1.methodN(Class1.java:458) at pkg2.ClassZ.methodUpdate(ClassZ.java:458) at … at java.lang.Thread.run(Thread.java:595) 06:05:57 07.11.2011 INFO (Class1.java:41) User ‘bfernan’ Start method1 06:05:57 07.11.2011 INFO (Class1.java:44) Before retrieve information from DB 06:05:57 07.11.2011 INFO (Class1.java:46) After retrieve information from DB 06:05:57 07.11.2011 INFO (Class1.java:50) Updating information 06:05:57 07.11.2011 INFO (Class1.java:94) Before save information in the DB 06:05:58 07.11.2011 INFO (Class1.java:96) After retrieve information in the DB 06:05:58 07.11.2011 INFO (Class1.java:100) User ‘bfernan’ Finish method1 06:05:58 07.11.2011 INFO (Class1.java:41) User ‘bfernan’ Start method1 06:05:58 07.11.2011 INFO (Class1.java:44) Before retrieve information from DB 06:05:58 07.11.2011 INFO (Class1.java:46) After retrieve information from DB 06:05:59 07.11.2011 INFO (Class1.java:50) Updating information 06:05:59 07.11.2011 INFO (Class1.java:94) Before save information in the DB 06:05:59 07.11.2011 INFO (Class1.java:96) After retrieve information in the DB 06:05:59 07.11.2011 INFO (Class1.java:100) User ‘bfernan’ Finish method1 Спасибо! Benedicto Fernandez Software Engineer CERN / GS-AIS

More Related