The Holy Java

Building the right thing, building it right, fast

Posts Tagged ‘logging’

Most interesting links of August ’13

Posted by Jakub Holý on August 31, 2013

Sorry folks, this month it will be very brief. I have many more great stuff in the queue but haven’t managed to write it down yet. Next month will be heavy :-)

Recommended Readings

  • Interested in native vs. webapp? Check out Why mobile web apps are slow (mobile browser much slower, not much real improvements, weak CPUs,…; seems to be really high-quality, plenty of data) and Sencha’s 5 Myths About Mobile Web Performance (Mobile web performance is mostly driven by JavaScript performance on the CPU, CPU-Bound JavaScript has only become faster because of HW improvements, Mobile browsers are already fully optimized, Future hardware improvements are unlikely to help, JavaScript garbage collection is a performance killer).
  • Why Software Projects are Terrible and How Not To Fix Them – many teams are not ready to embrace new/better software practices, primarly for two reasons: 1) most of them are nonintuitive (f.ex. adding more people will slow dev down) and need to be sold through a high hierarchy of managament – but people/managers/organizations don’t really care, it takes years for good/bad practices to have an impact, which is not relevant “now.” 2) Businss objectives change too quickly and SW is blamed for not delivering. Based on evaluating many failed projects. Conclusion: Choose carefully people/organizations your work with. Avoid blame-driven ones. Quote on middle managers: “He has to put more developers on the project, call a meeting and yell at people, and other arbitrary bad ideas.  Not because he thinks those will solve the problem.  In fact, managers often do this in spite of the fact that they know it’s bad. Because that’s what will convince upper management that they’re doing their best.” “In the vast majority of failed projects I’ve been called to looked at, the managers have not read one book on software engineering.

Data & Analytics

  • Big Data: Kafka for uSwitch’s Event Pipeline – a better alternative to log files – use LinkedIn’s Kafka for messaging, have MR jobs to import latest messages into Hadoop/HDFS. The advantage of Kafka is that it persists the messages for a period of time so it is easy to batch-import and even re-import them. The uSwitch’s talk Users As Data explains the downsides of log files. LinkedIn’s Camus is a tool for importing messages from Kafka to HDFS.
  • Realtime Analytics with Storm and Hadoop (at Twitter; presentation deck) – pre-aggregate some data into a read-only, random read DB such as ElephantDB, Voldemort, or Manhattan. For newer data use Storm and aggregated data in a read-write, big-data DB such as HBase, Riak, or Cassandra. For stuff that cannot be pre-aggregated you might use Storm’s Distributed RPC.
  • The Unified Logging Infrastructure for Data Analytics at Twitter – a paper from late 2012 that presents “Twitter’s production logging infrastructure and its evolution from application-specific logging to a uni- fied “client events” log format, where messages are captured in common, well-formatted, flexible Thrift messages” – with the benefit of “s streamlined log collection and data analysis”.

Other

  • Development and Deployment at Facebook (Kent Beck et. al., 8/2013, 13p paper) – “More than one billion users log in to Facebook at least once a month to connect and share content with each other. Among other activities, these users upload over 2.5 billion content items every day. In this article we describe the development and deployment of the software that supports all this activity, focusing on the site’s primary codebase for the Web front-end.

Talks

  • One of the most valuable talks I’ve seen, in just 18 min: The Progress Principle – about the disengagement crisis and motivation at work by Teresa Amabile at TEDx Atlanta (via @thovden). Disengagement from work is increasing, at all age and salary levels, and leads to unhappy people, low productivity, huge financial losses. Based on analysing diaries of 12k participants, the single most important engaging and motivating factor is making progress in a meaningful work (including small wins). A culture of management by fear and punishment for failure creates disengagement and can crush even an innovative, profitable, praised company in a few years. Everybody, though especially the management, creates the culture through their everyday, small actions. If everybody focuses on catalysing progress and supporting their fellow humans through good and bad times, engagement and success will follow. Remove progress inhibitors, nourish the human spirit (acknowledge what we humans value, encourage people). Yet of the managers asked, very few knew of the significance of making progress (or, I can assume, of supporting people and making them happy(er) and the impact of our inner work life (perceptions, emotions, etc.) on our productivity and creativity). The study included two seemingly similar, successfull companies, one with great engagement, another with a new management that managed to destroy the engagement and thus eventually the company. Actions to take: catalyse progress, celebrate wins, encourage and support your colleagues.

Clojure Corner

  • Wonderful Clojure Cheatsheet 1.5 with tooltips showing the doc and summary of information available at clojuredocs.org (other Clj versions), by Andy Fingerhut
  • Chas Emerick’s Clojure type selection flowchart to help you decide whether to use a map, a record, reify, proxy, gen-class, or deftype.  (Reify and proxy don’t produce a class but just an instance of an anonymous class; proxy can extend a base class, reify cannot. gen-class produces a class visible from Java and can extend Java classes.  …)

Tools/Libs

  • Docker.io – pack, ship and run any application (and its dependencies) as a lightweight container, i.e. essentially “a VM without the overhead of a VM,” using linux containers (chroot on steroids with resource limits via control groups) see reports of some uses such as Java app deployment, desktop virtualization, automatic app deployment in GitHub commit. Docker also supports evolving the containers over time, i.e. deploying new version, by pushing just diffs so it’s low-overhead. You can build a container (include files, SW, forward ports, …) using a Dockerfile. See dotScale 2013 – Solomon Hykes – Why we built Docker for an intro (20 min).
  • Packer.io – tool for building pre-configured VM images for different platforms (EC2, VirtualBox, …), remotely similar to Netflix’s Aminator. See Immutable Servers With Packer and Puppet for an example use case.
  • Ubuntu-build Vagrant boxes at cloud-images.ubuntu.com/vagrant/
  • SlimerJS – PhantomJS-compatible headless browser engine based on Firefox/Gecko (well, it is not fully headless yet but that is planned; the main focus now is full compatibility with PhantomJS’ API) (Both work with CasperJS for navigational steps/testing.)
  • localtunnel – instantly show locally running webapp/server to the rest of the world (gem install localtunnel,  localtunnel <port to share>, => share the url returned, e.g. http://xyz.localtunnel.com) – I haven’t tried it but it looks simple and very convenient
  • Logstash + Kibana (via @mortenberg): take control of your logs – while Logstash can collect (from multiple servers/services), parse (over 100 built-in patterns), store, index, search your logs, Kibana is a web interface to seach them, view them in realtime (based on a query) etc. See this Logstash slides (9/2012) and an overview of Kibana’s powers. PS: Logstash can also compute metrics and send them to graphite etc. It is typically used with ElasticSearch.
  • ncdu is an interactive, command-like disk usage browser that shows a list of directories sorted by size shown in human-friendly units, you can navigate with arrows and enter and i to show the current dir/file info, d to delete it, q to quit; check out this article about ncdu with screenshots and ncdu man page. Install via Apt etc., run f.ex. with ncdu -x / .
  • vagrant-cachier – Vagrant plugin for caching apt/yum/.. packages locally, thus speeding up destroy+up

Posted in General, Tools, Top links of month | Tagged: , , , , , , , , | 2 Comments »

Most interesting links of November ’12

Posted by Jakub Holý on November 30, 2012

Recommended Readings

  • James Roper: Scaling Scala vs Java (recommended by M. Odersky) – writing scalable apps in Scala is much easier then Java because idiomatic Scala uses immutable structures and lends itself naturally to asynchronous processing while doing these things in Java is possible but very unnatural and laborious. “It [Scala] is biased towards scaling, it encourages practices that help you scale.”
  • Exception Handling Antipatterns (2006, still valuable) – Log and Throw, Throwing Exception (instead of a suitable subclass), Throwing the Kitchen Sink (declaring many exceptions in method signature), Catching Exception (instead of a particular subclass), Destructive Wrapping (not including the exception as cause), Log and Return Null, Catch and Ignore (swallowing the exception), Throw from Within Finally, Multi-Line Log Messages (via repeated log calls instead of \n), Ignoring InterruptedException (instead of breaking the loop etc.), Relying on getCause().
  • The GitHub way: Your team should work like an open source project – a provocative article about the development process in GitHub that strongly prefers asynchronous and on-line communication over face-to-face meetings and communication, which, according to the author, leads to increased productivity. That is quite the opposite of what is usually practiced. I can think of situation where direct interaction is invaluable but, on the other hand, I could certainly live with less meetings. (Comments on Hacker News)

Clojure Corner

  • Chas Emerick’s screencast Starting Clojure is a great example of Clojure development and interactive Clojure web development without restarts, with live code changes and direct access to the running app via REPL. It makes also a good job of introducing the Eclipse Clojure plugin Counterclockwise and the popular web framework Compojure with the template engine Enlive and HTTP abstraction Ring. Highly recommended! (I would however recommend to already know a little about the language.)
  • Results of the 2012 State of Clojure survey (and, for comparison, 2010 results) – some interesting facts are what people use Clojure for (math / data analysis 35%, web development 70%), 60% people evaluating ClojureScript, answers to “What have been the biggest wins for you in using Clojure?”, the fact that ~ 20% use Eclipse, around 60% Emacs, only 10% IntelliJ, 23% vim. Also interesting is “What has been most frustrating for you in your use of Clojure” (with 30% mentions of documentation, being now improved by clojure-doc.org, 23% “future stuffing concerns”)

Favorite Quotes

You can reach a point with Lisp where, between the conceptual simplicity, the large libraries, and the customization of macros, you are able to write only code that matters.

- Rich Hickey in an interview

Lisp was a piece of theory that unexpectedly got turned into a programming language.

- Paul Graham in Revenge of the Nerds

Posted in General, Languages, Top links of month | Tagged: , , , , | Comments Off

Most interesting links of January ’12

Posted by Jakub Holý on January 31, 2012

Recommended Readings

  • Jeff Sutherland: Powerful Strategy for Defect Prevention: Improve the Quality of Your Product – “A classic paper from IBM shows how they systematically reduced defects by analyzing root cause. The cost of implementing this practice is less than the cost of fixing defects that you will have if you do not implement it so it should always be implemented.” – categorize defects by type, severity, component, when introduced; 80% of them will originate in 20% of the code; apply prioritized automated testing (solve always the largest problem first). “In three months, one of our venture companies cut a 4-6 week deployment cycle to 2 weeks with only 120 tests.”
  • Ebook draft: Beheading the Software Beast – Relentless restructurings with The Mikado Method (foreword by T. Poppendieck) – the book introduces the Mikado Method for organized, always-staying-green (large-scale) refactorings, especially useful for legacy systems, shows it on a real-world example (30 pages!), discusses various application restructuring techniques, provides practical guidelines for dealing with different sizes of refactorings and teams, discusses in depth technical debt and more. To sum it up in three words: Check it out!
  • Daily Routine of a 4 Hour Programmer (well, it’s actually about 4h of focused programming + some hours of the rest) – a very interesting reading with some inspiring ideas. We should all find some time to follow up the field, to reflect on our day and learn from it (kaizen)
  • The Agile Testing Quadrants – understanding the different types of tests, their purpose and relation by slicing them by the axis “business facing x technology facing” and the axis “supporting the team x critiquing the product” => unit tests x functional tests x exploratory testing x performance testing (and other). It helps to understand what should be automated, what needs to be manual and helps not to forget all the dimensions of testing.
  • Adam Bien: Can stateful Java EE apps scale? – What does “stateless” really mean? “Stateless only means, that the entire state is stored in the database and has to synchronized on every request.” “I start the development of non-trivial (>CRUD) applications with Gateway / PDOs [JH: stateful EJBs exposing JPA entities] and measure the performance and memory consumption continuously.” Some general tips: Don’t split your web server and servlet container, don’t use session replication.
  • Brian Tarbox: Just-In-Time Logging – How to remove 90% of worthless logs while still getting detailed logs for cases that matters – the solution is to (1) only add logs for a particular “transaction” with the system into a runtime structure and (2) flush it to the log only if the transaction fails or st. else significant happens with it. The blog also proposes a possible implementation in detail.
  • DZone’s Top 10 NoSQL Articles of 2011
  • DZone’s Top 5 DevOps Articles of 2011
  • Test Driven Infrastructure with Vagrant, Puppet and Guard – this is interesting for me for I’m using Vagrant and Puppet on my project to create and share development environments or their parts and applying test-first approach to it seems interesting as do also the tools, rspec-puppet, cucumber-puppet and Guard (events triggered by file changes) and referenced articels.
  • 5+1 Sonar Plugins you must not miss (2012 version) – Timeline Plugin (with Google Visualization Annotated TimeLine), Useless Code Plugin, SIG Maintainability Model Plugin (metrics Analysability, Changeability, Stability, Testability), Quality Index Plugin (1-number health indicator), Technical Debt Plugin

Links to Keep

Clojure Corner

  • ClojureScript One Guide – “ClojureScript One shows you how to use ClojureScript to build single-page, single-language applications in a productive, effective and fun way.”
  • Asynchronous workflows in Clojure – true asynchronous (non-blocking) network access in Clojure with Netty/the Lamina project.
  • Clojure 2011 Year in Review – a list with important events in the Clojure sphere with links to details – C. 1.3.0, ClojureScript, logic programming with core.logic, clojure-contrib restructuring, birth of 4Clojure and Avout.
  • Clojure Atlas – interesting project (alpha version) presenting Clojure documentation in the form of interactive graph of related concepts and functions; it’s far from perfection but I like the concept and consider paying those ~ $25 for the 1.3.0 version when its out (however, the demo is free and it might become open-sourced in 2012)

Posted in General, Languages, Testing, Tools, Top links of month | Tagged: , , , , , , , , , , | Comments Off

AWK: Extract Logs for the Given Date(s) from a Log File

Posted by Jakub Holý on December 18, 2011

If your log file has entries like these:

2011-12-10T22:00:27.996+0000 [http-8080-1] INFO  my.package.MyClass Hello, I'm alive!
2011-12-11T17:05:46.811+0000 [http-8080-15] ERROR my.package.MyClass  - Error caught in DispatcherServlet
        at my.package.MyServiceClass(MyServiceClass.java:36)
...
2011-12-11T17:06:10.120+0000 [http-8080-14] DEBUG my.package.MyClass Whoo, that has been a long day!

Then you can use the following bash script snippet to extract logs only for a particular day or consecutive days, including everything – even lines not starting with the date such as stacktraces – between the first log of the date up to the first log of a subsequent date (default: yesterday):

LOGFILE_ORIG="$0"; LOGFILE="${LOGFILE_ORIG}.subset"
if [ -z "$LOGDAY" ]; then LOGDAY=$(date +%F -d "-1 days"); fi
if [ -z "$AFTERLOGDAY" ]; then AFTERLOGDAY=$(date +%F -d "$LOGDAY +1 days"); fi
echo "Extracting logs in the range (>= $LOGDAY && < $AFTERLOGDAY) into $LOGFILE ..." awk "/^$LOGDAY/,/^$AFTERLOGDAY/ {if(!/^$AFTERLOGDAY/) print}" $LOGFILE_ORIG > $LOGFILE

This date format works on Linux. Date is very flexible and can provide dates in any format, not only yyyy-mm-dd. You may also want to read more about Awk ranges and other tips.

You would run it in one of the following ways:

$ ./analysis.sh /path/to/logfile.log
$ LOGDAY=2011-12-12 AFTERLOGDAY=2011-12-17 ./analysis.sh /path/to/logfile.log

Posted in General, Tools | Tagged: , , | Comments Off

Intro: Java Webapp Monitoring with Hyperic HQ + How to Alert on Too Many Errors in Logs

Posted by Jakub Holý on October 17, 2011

This post describes how to set up the Java-based open source monitoring tool Hyperic HQ to monitor application server error logs and send a single warning e-mail when there are more of them than a threshold. In the previous post Aggregating Error Logs to Send a Warning Email When Too Many of Them – Log4j, Stat4j, SMTPAppender we’ve seen how to achieve that programatically while this solution is just about configuration. We will also see a little what else (a lot!) Hyperic can do for you and what the impressions after a short experimentation with it are. Read the rest of this entry »

Posted in j2ee, Tools | Tagged: , , , | Comments Off

Aggregating Error Logs to Send a Warning Email When Too Many of Them – Log4j, Stat4j, SMTPAppender

Posted by Jakub Holý on October 15, 2011

Our development team wanted to get notified as soon as something goes wrong in our production system, a critical Java web application serving thousands of customers daily. The idea was to let it send us an email when there are too many errors, indicating usually a problem with a database, an external web service, or something really bad with the application itself. In this post I want to present a simple solution we have implemented using a custom Log4J Appender based on Stats4j and an SMTPAppender (which is more difficult to configure and troubleshoot than you might expect) and in the following post I explore how to achieve the same effect with the open-source Hyperic HQ monitoring SW.

Read the rest of this entry »

Posted in j2ee, Tools | Tagged: , , , | 1 Comment »

Most interesting links of May

Posted by Jakub Holý on May 31, 2011

Recommanded Readings

Acceptance testing / Specification by example:

  • Gojko Adzic: Anatomy of a good acceptance test – an example of refactoring a bad acceptance test into a good one – good for learning about pitfalls and how a good one should look like
  • Gojko: Top 10 reasons why teams fail with Acceptance Testing – acceptance testing is great and brings lot of value but must not be underestimated; some of the problems are bad collaboration, focusing on “how” instead of “what,” confusing AT with full regression tests. Brief, worth reading.
  • Specification by Example: a love story (go directly to the PDF with the story): A nice, made-up story of going from low-level, workflow-based Selenium tests through similar Cucumber ones to true BDD tests describidng clearly what, not how – very well shows the point of specification by example and how it should (and should not) look like

(Enterprise) Java best practices:

  •  Clean code, clean logs: 10 brief posts on logging best-practices – nothing really new here for me but in total it is a very good overview that every developer should know
  • Make Large Scale Changes Incrementally with Branch By Abstraction – Continuous integration doesn’t work well with branches but as this article shows, you can manage even large-scale refactorings without branches using “branch by abstraction,” an approach reminding me of Fowler’s “strangler application” (an incremental replacement of a legacy system). The idea is: 1. Create an abstraction over the part of code to be changed;  2. Refactor the code to use it; 3. Implement new functionality using the new way / step by step move old functionality too, the abstraction layer delegating either to the new or old implementation … . It may be more work but: 1) your software is always working and deliverable; 2) (side-effect) in the end it will be more decoupled

Git:

  • John Wiegley’s Git from the bottom upp (31p, Git 1.5.4.5, PDF) – a useful explanation of the fundamentals of Git, i.e. how it is constructed and how it works, which makes it much easier to understand how to  use it properly (recommended by Pål R.). Reading the The Git Parable first may be a good idea for an easy introduction into the fundamentals, though absolutely not necessary. This document introduces very well the important Git concepts (blob, index, commit, commit names such as branches, reflog) and how they cooperate to provide the rich set of functionality it has. It also explains well the value and usage of rebase. Among others I’ve appreciated the tip to use checkout, branch -m <new-branch> master, branch -D instead of the much more dangerous reset –hard and the tip to use stash / stash apply to create daily backups of your working tree in the reflog (with clearing it with ‘git reflog expire –expire=30.days refs/stash‘ instead of stash clear). Also git diff/log master..[HEAD] for reviewing work done in the current branch and and git diff/log ..master for checking the changes since the last merge/rebase after a fetch are interesting.

Tools:

  • The secret power of bookmarklets – bookmarklets are an indispensable tool for every developer who works with web applications (to fill in test data, speed up log in, …), yet I’m sometimes surprised by meeting people who don’t know or use them; this blog explains them nicely, links to some useful ones and some useful tools for building them

Recommended Books

  • (*****) Implementing Lean Software Development: From Concept to Cash by Mary Poppendieck, Tom Poppendieck – A great introduction into lean thinking (the values and principles it is build upon), clearly communicated with the help of “war stories”. I absolutely recommend it to anybody interested in lean/agile.
  • (**** ) Agile Project Management with Scrum (Microsoft Professional) by Ken Schwaber – Even though you can’t understand Scrum without experiencing it, this book full of war stories will help you to avoid many Scrum implementation pitfalls and to understand its mantra of “the art of the possible” and will show you how to adapt Scrum to various situations. It’s very easy to read thanks to its format of brief case studies organized by topics (team, product owner, …).

Favourite Quotes of the Month

@unclebobmartin: Cleaning code does NOT take time. NOT cleaning code does take time.

Posted in General, Languages, Testing, Tools, Top links of month | Tagged: , , , , , , , , , , | Comments Off

Troubleshooting logging configuration (Log4j, commons-logging)

Posted by Jakub Holý on December 7, 2009

Did it ever happen to you that your logging didn’t behave as expected? Here are some tips how to find out what’s going on.

Commons-logging (since 1.1)

Set the system property org.apache.commons.logging.diagnostics.dest to STDOUT (or STDERR or a file name); docs: -Dorg.apache.commons.logging.diagnostics.dest=STDOUT

Extract of a sample output (no commons-logging.properties):

...
[LogFactory from sun.misc.Launcher$AppClassLoader@934873913] [ENV] Application classpath (java.class.path): ..
...
[LOOKUP] No properties file of name 'commons-logging.properties' found
....
Discovering a Log implementation...
...
Log adapter 'org.apache.commons.logging.impl.Log4JLogger' from classloader java.net.URLClassLoader@32689826 has been selected for use.

Extract of a sample output (incorrect commons-logging.properties found):

...
[LogFactory from sun.misc.Launcher$AppClassLoader@934873913] [LOOKUP] Properties file found at 'jar:file:/myproject/lib/test/dbunit-embeddedderby-parenttest-sources.jar!/commons-logging.properties' with priority 0.0
.. [LOOKUP] Properties file at 'file:/myproject/web/WEB-INF/classes/commons-logging.properties' with priority 0.0 does not override file at 'jar:file:/myproject/lib/test/dbunit-embeddedderby-parenttest-sources.jar!/commons-logging.properties' with priority 0.0
.. [LOOKUP] Properties file of name 'commons-logging.properties' found at 'jar:file:/myproject/lib/test/dbunit-embeddedderby-parenttest-sources.jar!/commons-logging.properties"
.. Attempting to load user-specified log class 'org.apache.commons.logging.impl.SimpleLog'...
.. Log adapter 'org.apache.commons.logging.impl.SimpleLog' from classloader sun.misc.Launcher$AppClassLoader@934873913 has been selected for use.
...

Notice that Commons Logging uses the context classloader and not e.g. Class.getClassloader() to locate the implementation to use, which may occassionally lead to some problems.

PS: You may be better of not using commons-logging because of its classloader issues. (SLF4J may be better?)

Log4j

Set the system property log4j.debug to true for Log4j to log the location of the configuration file it’s using and other useful information. You can also set it in in the log4j.properties file:

log4j.debug=true

Or, as mentioned above, pass it as a system property to Java, for example as in

java -Dlog4j.debug=true -jar YourApplication.jar

The debug information will be printed into the System.out, not in any log file you may have configured (Log4j can’t use itself for this logging).

Example output:

log4j: Parsing for [root] with value=[INFO, CONSOLE, filelog].
log4j: Level token is [INFO].
log4j: Category root set to INFO
log4j: Parsing appender named "CONSOLE".
log4j: Parsing layout options for "CONSOLE".
log4j: Setting property [conversionPattern] to [%6rms [%p] ..%0.46c %x- %m%n].
log4j: End of parsing for "CONSOLE".
log4j: Parsed "CONSOLE" options.
log4j: Parsing appender named "filelog".
log4j: Parsing layout options for "filelog".
log4j: Setting property [conversionPattern] to [%6rms [%p] ..%0.46c %x- %m%n].
log4j: End of parsing for "filelog".
log4j: Setting property [file] to [/home/me/mylog.log].
log4j: Setting property [maxBackupIndex] to [5].
log4j: Setting property [maxFileSize] to [50MB].
log4j: setFile called: /home/me/mylog.log, true
log4j: setFile ended
log4j: Parsed "filelog" options.
log4j: Parsing for [eu.ibacz.lqs.uiradrupdater] with value=[DEBUG].
log4j: Level token is [DEBUG].
log4j: Category eu.ibacz.lqs.uiradrupdater set to DEBUG
log4j: Handling log4j.additivity.eu.ibacz.lqs.uiradrupdater=[null]
log4j: Finished configuring.

For the log4j.properties:

log4j.rootCategory=INFO, CONSOLE, filelog

log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=%6rms [%p] ..%0.46c %x- %m%n

log4j.appender.filelog=org.apache.log4j.RollingFileAppender
log4j.appender.filelog.File=${user.home}/mylog.log
log4j.appender.filelog.MaxFileSize=50MB
log4j.appender.filelog.MaxBackupIndex=5
log4j.appender.filelog.layout=org.apache.log4j.PatternLayout
log4j.appender.filelog.layout.ConversionPattern=%6rms [%p] ..%0.46c %x- %m%n

log4j.logger.eu.ibacz.lqs.uiradrupdater=DEBUG

Posted in Languages, Tools | Tagged: , , , , , | Comments Off

A logging wrapper around PreparedStatement to provide detailed info upon error

Posted by Jakub Holý on May 23, 2009

In my java web application I use JDBC to store data in batches into a database. When there is a problem the whole batch insert fails and it’s difficult to find out what data caused it to fail. Therefore I’ve created a wrapper around PreparedStatement that remembers values passed into the various set* methods and can provide a comma-separated listing of all rows in the batch upon failure.

This is my LoggingStatementDecorator that stores values for later logging; based on java.lang.reflect.Proxy:

package eu.ibacz.example;

import java.lang.reflect.InvocationHandler;
import java.lang.reflect.InvocationTargetException;
import java.lang.reflect.Method;
import java.lang.reflect.Proxy;
import java.sql.PreparedStatement;
import java.util.LinkedList;
import java.util.List;

/**
 * Remember values passed into a sql statement via setString etc. for later logging. 
 */
class LoggingStatementDecorator implements InvocationHandler {
    
    /** File's Subversion info (version etc.). */
    public static final String SVN_ID = "$id$";
    
    private List<List<Object>> batch = new LinkedList<List<Object>>();
    private List<Object> currentRow = new LinkedList<Object>();
    private PreparedStatement target;
    private boolean failed = false;
    
    public LoggingStatementDecorator(PreparedStatement target) {
        if (target == null) throw new IllegalArgumentException("'target' can't be null.");
        this.target = target;
    }


     // @see java.lang.reflect.InvocationHandler#invoke(java.lang.Object, java.lang.reflect.Method, java.lang.Object[]) */
    public Object invoke(Object proxy, Method method, Object[] args)
            throws Throwable {
        
        final Object result; 
        
        try {
            result = method.invoke(target, args);
            failed = false;
        } catch (InvocationTargetException e) {
            failed = true;
            throw e.getTargetException();
        } catch (Exception e) {
            failed = true;
            throw e;
        }
        
        if ( method.getName().startsWith("setNull") 
                && (args.length >=1 && Integer.TYPE == method.getParameterTypes()[0] ) ) {
            handleSetSomething((Integer) args[0], null);
        } else if ( method.getName().startsWith("set") 
                && (args.length >=2 && Integer.TYPE == method.getParameterTypes()[0] ) ) {
            handleSetSomething((Integer) args[0], args[1]);
        } else if ("addBatch".equals(method.getName())) {
            handleAddBatch();
        }
        
        return result;
    }
    
    private void handleSetSomething(int index, Object value) {
        currentRow.add(value);
    }
    
    private void handleAddBatch() {
        batch.add(currentRow);
        currentRow = new LinkedList<Object>();
    }
    
    public List<List<Object>> getValues() {
        return batch;
    }
    
    public PreparedStatement getTarget() { return target; }
    
    /** Has the last method called on the Statement caused an exception? */
    public boolean isFailed() { return failed; }
    
    public String toString() { return "LoggingHandler[failed="+failed+"]"; }
    
    /** Values as comma-separated values. */
    public String getValuesAsCsv() {
        StringBuilder csv = new StringBuilder();
        for (List<Object> row : getValues()) {
            for (Object field : row) {
                // Escape Strings
                if (field instanceof String) {
                    field = "'" + ((String) field).replaceAll("'", "''") + "'";
                }
                csv.append(field).append(",");
            }
            csv.append("\n");
        }
        return csv.toString();
    } /* getValuesAsCsv */
    
    public PreparedStatement createProxy() {
        return (PreparedStatement) Proxy.newProxyInstance(
                PreparedStatement.class.getClassLoader(),
                new Class[] { PreparedStatement.class },
                this);
    };
    
}

And this is how you use it:

        // ...
        PreparedStatement stmt = null;
        try {
            LoggingStatementDecorator stmtHandler = new LoggingStatementDecorator( connection.prepareStatement("insert into mytable values(?,?)") );
            stmt =  stmtHandler.createProxy();
            
            // add data to the batch
            for(int i=0; i<10; ++i) {
                stmt.setInt(1, i);
                stmt.setString(2, "Row number " + i);
                stmt.addBatch();
            }
            
            stmt.executeBatch();
            
        } catch (SQLException e) {
            // ... some rollback etc.
            
            LoggingStatementDecorator stmtHandler = (LoggingStatementDecorator)
                    ((stmt instanceof Proxy)? Proxy.getInvocationHandler(stmt) : null);
                // TODO include the insert sql in the log!!!
                StringBuilder log = new StringBuilder();
                log = buildFailureInfo("mytable", stmtHandler, log);
                LOG.error("Failure while processing data:" + log, e);
            }
        }
            

    private StringBuilder buildFailureInfo(String table, LoggingStatementDecorator stmtHandler, StringBuilder details) {
        
        if (stmtHandler != null && stmtHandler.isFailed()) {
            // Already insertion of records failed
            details.append("\nInsert of records failed. Table=").append(table)
                .append("), values=[\n").append(stmtHandler.getValuesAsCsv()).append("]");
            
        }
        
        return details;
    } /* buildFailureInfo */

When an excepion occures, you get nice log that shall tell you all you need to detect the problem or reproduce it.

Fotnote: Of course I could have perhaps used the open-source P6Spy but I’m afraid it would log more than I need (I believe it to be bound to a data source, not a particular webapp’s PreparedStatement).

Posted in Languages | Tagged: , , , , | Comments Off

Injecting better logging into a binary .class using Javassist

Posted by Jakub Holý on October 2, 2008

Have you ever been strucked by a completely useless exception message somewhere from the depth of a 3rd party application or library you had to use in your code? Have you ever wanted the bloody nameless programmer to have written a truly informative and helpful error message so that you wouldn’t need to spend hours trying to figure out what was the problem that would have been easily discovered if only more context information available at the moment when the exception occured was included in its error message? Have you wondered how only you could inject the necessary logging into the spot? Read on to get the answer.

Update 6/2010: You may also want to read the follow-up blog Implementing build-time bytecode instrumentation with Javassist.

Recently I was testing my extension to Saba, a monstrous J2EE learning management system, and got an exception from a Saba class saying that the expected and actual data types of a custom attribute don’t match.  The problem was that I had no idea which one of the 10s of custom attributes could be the cause and I even wasn’t sure which object’s attributes I should check. It would be so much easier if the “nameless bloody Saba programmer” (no offense :-)) included the attribute’s name and preferably also its actual & expected data types and the actual and new values. How could I insert there logging of these properties? Needless to say that I had to use Java 1.4 (no agents…) and couldn’t afford more than modifying this single class file (i.e. no additional libraries etc.) because the changes I could do to the development environment where the application ran were limited.

Of course the easiest would have been to decomile the class, add the loging before the exception is thrown, recompile it and replace it on the server. But not only is decompiling illegal here, it also sometimes simply doesn’t work. Fortunatelly there is another solution – JBoss Javassist is a byte code manipulation library that supports not only runtime manipulation but also post-comilation time manipulation, i.e. you can modify and save the class and use it to replace the original file. There are quite a few byte code manipulation libraries but Javassist has the great advantage that you don’t need to know much about bytecode, you can simply pass a String with java statements that should be inserted before/after/… method call or into a new catch statement. There is a nice tutorial that describes it (see part 4.1, Inserting source text at the beginning/end of a method body):

addCatch() inserts a code fragment into a method body so that the code fragment is executed when the method body
throws an exception and the control returns to the caller. In the source text representing the inserted code fragment,
the exception value is referred to with the special variable $e.

For example, this program:

      ClassPool pool = ClassPool.getDefault();
      CtClass compiledClass = pool.get("mypackage.MyClass");
      CtMethod m = compiledClass.getDeclaredMethod("myExceptionThrowingMethod");
      CtClass etype = ClassPool.getDefault().get("java.io.IOException");
      m.addCatch("{ System.out.println($e); throw $e; }", etype);

translates the method body represented by m into something like this:

      try {
          the original method body
      }
      catch (java.io.IOException e) {
          System.out.println(e);
          throw e;
      }

Note that the inserted code fragment must end with a throw or return statement.

You can use $e to access the exception, $0 to access “this”, $1 to access the 1st parameter of the method etc. At the end you just call compiledClass.writeFile(); and use the modified mypackage/MyClass.class to replace the original class in the application.

Lovely, isn’t it?

Posted in Languages | Tagged: , , | 4 Comments »