One of many daily activities that every programmer needs to do in order to do their work is to control logging output from their application. Logging, when done properly and correctly, provides great insight into the inner workings of the application and may be a great resource for analyzing and optimizing your codes behavior. Whether it is during development or maintenance/support phase of the product life-cycle, this task is often considered to be unpleasant for many programmers. But since log analysis is so important and often required there usually isn’t simple way around. In this article I will present an elegant solution to reviewing logs in development stage of the application within IDE.
If you happen to be a programmer involved in development of an enterprise application you are pretty aware of sizes your applications logs can grow up to. Given sizes and complexity of these logs, it is often quite a tacky task to find certain events of interest. In our team, we identified three basic events of interest common for all the applications in our portfolio:
- Execution of an SQL expression
- Beginning and end of an transaction
- Web service request & response
Grep console
Given our development practices and the fact that Spring framework backs most of our products, our favorite IDE is Spring Tool Suite (STS for short). And since STS is build on top of Eclipse IDE it comes with vast Eclipse Marketplace. If you look deep enough you just might find everything there. Among many useful tools and plugins, Marketplace also stores one small but powerful plugin called Grep console. This little project is developed and maintained by Marian Schedenig. What it does is it allows you to define a set of styles that are applied to your logging console based on assigned regular expressions.
If you are like me and default Eclipse theme (fonts, colors, font sizes and stuff) is just not working for you, than you are probably using some plugins to tweak your IDEs look. I personally prefer Eclipse Color Themes plugin and Gedit Original Oblivion theme. Great thing about this project is that whole theme settings are available online in a nicely presented way. And this is where things get interesting. This allows programmer to create consistent style across code and logs providing really easy and intuitive way of organizing your thoughts and improves your overall orientation.
Grep console in action
Following paragraphs are showcasing applied styles for three mentioned events of interest.
Execution of an SQL expression
One of the most basic tasks of analyzing logs is to locate execution of certain SQL expression. We use datasource-proxy for SQL logging purposes in our project, which provides proxy classes for JDBC API to intercept executing queries. Because of this we were able to easily map Grep consoles regexp to CommonsQueryLoggingListener class that logs any data-source interaction. Given our local style settings this is what one sees in console view within Eclipse IDE.
Color: #1eff67
Expression: .*net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener.*
2013-11-18 09:00:08,893 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:1, Num:1, Query:{[select SQ_S_SYS_MON.nextval from dual][]}
2013-11-18 09:00:08,896 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:2, Num:1, Query:{[insert into S_SYS_MON (COL_A, COL_B, COL_C) values (?, ?, ?)][1, 2013-11-18 08:59:07.872, A]}
2013-11-18 09:01:10,920 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:1, Num:1, Query:{[select SQ_S_SYS_MON.nextval from dual][]}
2013-11-18 09:01:10,924 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:3, Num:1, Query:{[insert into S_SYS_MON (COL_A, COL_B, COL_C) values (?, ?, ?)][2, 2013-11-18 09:59:07.872, B]}
2013-11-18 09:02:12,946 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:1, Num:1, Query:{[select SQ_S_SYS_MON.nextval from dual][]}
2013-11-18 09:02:12,949 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:2, Num:1, Query:{[insert into S_SYS_MON (COL_A, COL_B, COL_C) values (?, ?, ?)][3, 2013-11-18 10:59:07.872, C]}
2013-11-18 09:03:14,971 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:1, Num:1, Query:{[select SQ_S_SYS_MON.nextval from dual][]}
2013-11-18 09:03:14,974 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:2, Num:1, Query:{[insert into S_SYS_MON (COL_A, COL_B, COL_C) values (?, ?, ?)][4, 2013-11-18 11:59:07.872, D]}
2013-11-18 09:04:16,999 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:2, Num:1, Query:{[select SQ_S_SYS_MON.nextval from dual][]}Beginning and end of an transaction
It is always a good idea to mind the transactions, even more so while debugging. With Grep console its really easy to find the relevant portion of log for given transaction. After applying proper expression and color style, whole transaction management becomes nicely visible in logs and won’t be buried in lines of log. As you can see the whole situation becomes instantly recognizable solely on the basis of color assignment.
Color: #ffff00
Expression: .*org.hibernate.transaction.JDBCTransaction.*
2013-11-18 08:36:51,211 [http-bio-8080-exec-6] DEBUG org.hibernate.transaction.JDBCTransaction – begin
2013-11-18 08:36:51,211 [http-bio-8080-exec-6] DEBUG org.hibernate.transaction.JDBCTransaction – current autocommit status: true
2013-11-18 08:36:51,212 [http-bio-8080-exec-6] DEBUG org.hibernate.transaction.JDBCTransaction – disabling autocommit
2013-11-18 08:36:51,223 [http-bio-8080-exec-6] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:8, Num:1, Query:{[select count(*) from ABC where a like ? order by b asc][AI%]}
2013-11-18 08:36:51,226 [http-bio-8080-exec-6] DEBUG org.hibernate.transaction.JDBCTransaction – commit
2013-11-18 08:36:51,229 [http-bio-8080-exec-6] DEBUG org.hibernate.transaction.JDBCTransaction – re-enabling autocommit
2013-11-18 08:36:51,230 [http-bio-8080-exec-6] DEBUG org.hibernate.transaction.JDBCTransaction – committed JDBC ConnectionWeb service request & response
Last event of interest for me is the receiving of SOAP request or response due to degree of integration required/provided by our application. By specifying following two expressions we are now able to track exactly the points when a message enters/leaves the realm of our application.
Color: #03abff
Expression: .*org.springframework.ws.client.MessageTracing.*
Expression: .*org.springframework.ws.server.MessageTracing.*
2013-11-18 10:31:48,288 [http-bio-8080-exec-3] TRACE org.springframework.ws.soap.saaj.support.SaajUtils – SOAPElement [com.sun.xml.internal.messaging.saaj.soap.ver1_1.Envelope1_1Impl] implements SAAJ 1.3
2013-11-18 10:31:48,315 [http-bio-8080-exec-3] TRACE org.springframework.ws.server.MessageTracing.received – Received request [<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsd="http://a.b.c.com/product/v1.0">
<soapenv:Header/>
<soapenv:Body>
<xsd:getItem>
<xsd:itemId>1</xsd:itemId>
</xsd:getItem>
</soapenv:Body>
</soapenv:Envelope>]
2013-11-18 10:31:48,319 [http-bio-8080-exec-3] TRACE org.springframework.ws.soap.saaj.support.SaajUtils – SOAPElement [com.sun.xml.internal.messaging.saaj.soap.ver1_1.Body1_1Impl] implements SAAJ 1.3
2013-11-18 10:31:48,321 [http-bio-8080-exec-3] DEBUG org.springframework.ws.server.endpoint.mapping.PayloadRootAnnotationMethodEndpointMapping – Looking up endpoint for [{http://a.b.c.com/product/v1.0}getItemRequest]
2013-11-18 10:31:48,321 [http-bio-8080-exec-3] DEBUG org.springframework.ws.soap.server.SoapMessageDispatcher – Endpoint mapping [org.springframework.ws.server.endpoint.mapping.PayloadRootAnnotationMethodEndpointMapping@7115660] maps request to endpoint [public com.c.b.a.v10.getItem com.c.b.a.ws.ws.endpoint.ItemQuery.getItem(com.c.b.a.v10.getItemRequestDocument)]
2013-11-18 10:31:48,324 [http-bio-8080-exec-3] TRACE org.springframework.ws.soap.saaj.support.SaajUtils – SOAPElement [com.sun.xml.internal.messaging.saaj.soap.ver1_1.Header1_1Impl] implements SAAJ 1.3
2013-11-18 10:31:48,325 [http-bio-8080-exec-3] DEBUG org.springframework.ws.soap.server.SoapMessageDispatcher – Testing endpoint adapter [org.springframework.ws.server.endpoint.adapter.GenericMarshallingMethodEndpointAdapter@16a77b1c]Conclusion
Using this plugin really simplifies the development process and frees your mind to worry about more important issues than browsing meters of logs. Setup is fairly simple and the only limit is your ability to locate the events of interest and create matching rules for them. Another great benefit is the ability to customize console logs the way your IDE looks providing uniform development environment. It is also great for team cooperation since by defining a common set of styles you will always encounter the same logging output even on your colleagues computer. I contacted the developer of Grep console and asked about the possibility of opening external files in Grep Console to have the styles applied and he said himself it is an interesting idea so we just might get this functionality in future releases of the plugin. All this being said I find the Grep Console to be one of the essential tools to enhance my development process and can honestly recommend using it.
| Reference: | Master your IDE logging with Grep console from our JCG partner Jakub Stas at the Jakub Stas blog. |
