Enable access log in JBoss application server

Go to %JBOSS_HOME%\server\default\deploy\jboss-web.deployer folder and you will find server.xml. The Access logger is disabled by default. Just un-comment the access logger section and restart the JBoss application server. Rest is taken care.

Here is the Access logger configuration.
<Valve className="org.apache.catalina.valves.FastCommonAccessLogValve" prefix="localhost_access_log." suffix=".log" pattern="common" directory="${jboss.server.home.dir}/log" resolveHosts="false" />
The access log file will be created with the name - "localhost_access_log.2014-02-06" . The file is rotated every day. However, if required, you can modify the file name by reconfiguring. Generally, I would prefer to name it like node1_hostname_access.log where hostname is the name of the server in which JBoss is running. This will allow me to process and analyze several log files in a cluster environment without any ambiguity.

As other standard servers support, JBoss also supports two log format patterns - 1) common and 2) combined.

Apart from common and combined, you can also customize the log format as you wish. I have customized to my requirement as follows: -
 
<Valve className="org.apache.catalina.valves.AccessLogValve"
                prefix="node1_hostname_access." suffix=".log"
                pattern="%a %A %u %t %r %s %T %b %S" directory="${jboss.server.home.dir}/log"
                resolveHosts="false" />

Please read https://docs.jboss.org/jbossweb/latest/config/valve.html for more information on the parameters.

See below sample access log generated.

127.0.0.1 10.xx.xx.xx- [06/Feb/2014:16:01:07 +0530] GET /web-console/ HTTP/1.1 304 0.007 - -
127.0.0.1 10.xx.xx.xx- [06/Feb/2014:16:01:07 +0530] GET /web-console/applet.jsp HTTP/1.1 200 0.041 444 93300E3B983D53F8BE5FB39901E48B6B
127.0.0.1 10.xx.xx.xx- [06/Feb/2014:16:01:07 +0530] GET /web-console/ServerInfo.jsp HTTP/1.1 200 0.060 4226 93300E3B983D53F8BE5FB39901E48B6B
127.0.0.1 10.xx.xx.xx- [06/Feb/2014:16:01:07 +0530] GET /web-console/css/jboss.css HTTP/1.1 304 0.000 - 93300E3B983D53F8BE5FB39901E48B6B
127.0.0.1 10.xx.xx.xx- [06/Feb/2014:16:01:07 +0530] GET /web-console/images/logo.gif HTTP/1.1 304 0.000 - 93300E3B983D53F8BE5FB39901E48B6B
127.0.0.1 10.xx.xx.xx- [06/Feb/2014:16:01:07 +0530] POST /web-console/Invoker HTTP/1.1 200 0.439 2245739 93300E3B983D53F8BE5FB39901E48B6B
127.0.0.1 10.xx.xx.xx- [06/Feb/2014:16:01:07 +0530] GET /web-console/%5bLorg/jboss/console/manager/interfaces/ResourceTreeNode.class; HTTP/1.1 404 0.001 1177 93300E3B983D53F8BE5FB39901E48B6B


Hope you liked the tip.

HTTP 500 error and Chunked encoding in OSB/WebLogic

Till recently, there was a strange issue seen in peak time with my production WebLogic Server. I have a bunch of Web Services deployed in CXF in WebLogic server. The message flow is as below: -

External Load balancer --> OSB --> External Load balancer --> (CXF in) Web Logic


While up to 95 to 98% of the requests sent to WebLogic had been processed successfully, the remaining requests were timed out in 30 seconds by WebLogic server. When I looked at the access log generated in the WebLogic server, all timed out requests had recorded with HTTP status code 500.  It took a while to understand, isolate and resolve the issue.

I did a thread dump analysis and saw several hogging threads with a kind of trace given below:


"[ACTIVE] ExecuteThread: '43' for queue: 'weblogic.kernel.Default (self-tuning)'" RUNNABLE native
         
                java.net.SocketInputStream.socketRead0(Native Method)
         
                java.net.SocketInputStream.read(SocketInputStream.java:129)
         
                weblogic.servlet.internal.PostInputStream.read(PostInputStream.java:142)
         
                weblogic.utils.http.HttpChunkInputStream.readChunkSize(HttpChunkInputStream.java:115)
         
                weblogic.utils.http.HttpChunkInputStream.initChunk(HttpChunkInputStream.java:74)
         
                weblogic.utils.http.HttpChunkInputStream.skip(HttpChunkInputStream.java:203)
         
                weblogic.utils.http.HttpChunkInputStream.skipAllChunk(HttpChunkInputStream.java:378)
         
                weblogic.servlet.internal.ServletInputStreamImpl.ensureChunkedConsumed(ServletInputStreamImpl.java:35)
         
                weblogic.servlet.internal.ServletRequestImpl.skipUnreadBody(ServletRequestImpl.java:194)
         
                weblogic.servlet.internal.ServletRequestImpl.reset(ServletRequestImpl.java:152)
         
                weblogic.servlet.internal.MuxableSocketHTTP.requeue(MuxableSocketHTTP.java:195)
         
                weblogic.servlet.internal.VirtualConnection.requeue(VirtualConnection.java:329)
         
                weblogic.servlet.internal.ServletResponseImpl.send(ServletResponseImpl.java:1538)
         
                weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1455)
         
                weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)
         
                weblogic.work.ExecuteThread.run(ExecuteThread.java:173)
After further investigation, I found that the WebLogic server was not receiving the message within the default POST TIMEOUT (30 seconds) configured in the WebLogic server. Increasing the time out value to 45 or 60 seconds did not help. It only aggravated the performance issue.

Let's look at how the issue was resolved. When you define a business service in Oracle Service Bus (OSB), you would have seen a parameter namely "Use Chunked Streaming Mode" under "HTTP Transport Configuration" section. The default value was configured as "Enabled". Apparently, the load balancer was not able to handle requests with chuncked encoding in peak time. It was unable to transmit the request message to the WebLogic server within the configured post timeout period. It can be validated against the thread dump shown above. After changing the value from "Enabled" to "Disabled", the 500 error has been eliminated permanently and now the server is in good health.

Thanks for reading this post and hope you liked the tip. Please feel free to post your comment here.

Connecting to a remote Oracle database host using SQL Plus

A small but very useful tip on connecting to local and remote Oracle databases using SQL Plus

You must be already aware of this - how to connect to a local database using SQL plus. If not, it is very simple as given below: -
sqlplus user/pass@sidname

But, do you know how to connect to a database which is running on a different host.The following command will help you to achieve this.

sqlplus "user/pass@(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(Host=xxx.xxx.x.xxx)(Port=1521))(CONNECT_DATA=(SID=sidname)))"

Hope you find this tip useful.

WebLogic stuck threads and java.net.SocketInputStream.socketRead0

If you are a WebLogic developer or an administrator, you would have rarely missed a very common issue - Stuck threads. When a WebLogic thread is unable to finish a task within 10 minutes (which is default), the thread is marked as "STUCK". When there are too many stuck threads in a server instance, then the health of the server instance will go into "Warning" state. It will be tempting for one to increase the stuck thread time from 10 minutes to say 20 minutes to avoid stuck threads. But, it will not solve the issue, only help postponing the issue. Let me share my experience with stuck threads here.

When I was contacted for help by the developers/support folks in my company, I immediately looked at the health of the server. It was in "Warning" state. The reason for "Warning" state was "ThreadPool has stuck threads". This clearly indicated that there were stuck threads for some reasons.

The immediate step I remembered was to take the thread dump of the WebLogic server instance. If you are not aware, the thread dump can be taken in three ways (may be more, I know only 3 :-) ): a) Kill -3 b) jstack or c) WebLogic admin console. After collecting the thread dump, carefully look at the dump - you will be able to see all the threads and respective state. In my case, I found the following stuck thread.

"[STUCK] ExecuteThread: '14' for queue: 'weblogic.kernel.Default (self-tuning)'" RUNNABLE native
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:129)
oracle.net.ns.Packet.receive(Packet.java:293)
oracle.net.ns.DataPacket.receive(DataPacket.java:92)
oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:174)
oracle.net.ns.NetInputStream.read(NetInputStream.java:119)
oracle.net.ns.NetInputStream.read(NetInputStream.java:94)
oracle.net.ns.NetInputStream.read(NetInputStream.java:79)
oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:122)
oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:78)
oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1040)
oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1016)
oracle.jdbc.driver.T4C8TTILob.receiveReply(T4C8TTILob.java:847)
oracle.jdbc.driver.T4C8TTIClob.read(T4C8TTIClob.java:227)
oracle.jdbc.driver.T4CConnection.getChars(T4CConnection.java:2652)
oracle.sql.CLOB.getChars(CLOB.java:288)
oracle.jdbc.driver.OracleClobReader.needChars(OracleClobReader.java:178)
oracle.jdbc.driver.OracleClobReader.read(OracleClobReader.java:141)
oracle.xml.parser.v2.XMLCharReader.fillBuffer(XMLCharReader.java:183)
oracle.xml.parser.v2.XMLByteReader.saveBuffer(XMLByteReader.java:450)
oracle.xml.parser.v2.XMLReader.fillBuffer(XMLReader.java:2363)
oracle.xml.parser.v2.XMLReader.tryRead(XMLReader.java:1087)
oracle.xml.parser.v2.XMLReader.scanXMLDecl(XMLReader.java:2922)
oracle.xml.parser.v2.XMLReader.pushXMLReader(XMLReader.java:269)
oracle.xml.parser.v2.XMLParser.parse(XMLParser.java:312)
oracle.xdb.XMLType.getDOM(XMLType.java:1806)
com.xxxxx.yyy.zzz.getAAAA(BBBBB.java:814)
com.xxxxx.businessdeligate.yyyyyy.getAAAA(BBBBBB.java:337)
sun.reflect.GeneratedMethodAccessor65.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
com.xxxxx.service.DDDDDD.processRequest(CCCCCC.java:33)
sun.reflect.GeneratedMethodAccessor64.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:124)
org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:82)
org.apache.cxf.jaxws.JAXWSMethodInvoker.invoke(JAXWSMethodInvoker.java:100)
org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:68)
org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:56)
org.apache.cxf.workqueue.SynchronousExecutor.execute(SynchronousExecutor.java:37)
org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:92)
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:207)
org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:73)
org.apache.cxf.transport.servlet.ServletDestination.doMessage(ServletDestination.java:79)
org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:256t)
org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160)
org.apache.cxf.transport.servlet.AbstractCXFServlet.invoke(AbstractCXFServlet.java:170)
org.apache.cxf.transport.servlet.AbstractCXFServlet.doPost(AbstractCXFServlet.java:148)
javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)
weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)
weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:300)
weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:183)
weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.doIt(WebAppServletContext.java:3686)
weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3650)
weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)
weblogic.security.service.SecurityManager.runAs(SecurityManager.java:121)
weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2268)
weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2174)
weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1446)
weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)
weblogic.work.ExecuteThread.run(ExecuteThread.java:173)

The stuck thread could occur because of several reasons including the following: -

1. Remote server that you are accessing could be taking more time than expected
2. Network delay

In an ideal situation, you should talk to your remote service provider to reduce the response time (case 1) or network owner to check the latency issue (case 2). They should fix the issues at their end which will help you in turn to eliminate the stuck threads. For some reasons, the resolution might be time consuming and you may require to put an immediate stop to stuck threads as it would lead to thread exhaustion and higher system resource utilization. It is an unwanted situation. As a workaround, you can try with configuring time outs.

Query time out
In several cases, I have seen "Statement.execute" taking more time or sometime hanging infinitely because the database was not responding properly. You would want to time out these execute calls to save yourself from stuck thread. If you use WebLogic connection pool, you can configure statement time out parameter to a value which is acceptable to your application, say 15 seconds. The another way of doing this is to configure "Statement.setQueryTimeout" in the java code which will provide you fine control over timeout.

Read time out
In my case, after configuring query time out, the number of stuck threads has gone down drastically. But, not fully solved and still few were left. Further investigation shown me that the thread was hanging because of socket read operation. After searching entire Web, I found a useful WebLogic JVM parameter  - oracle.jdbc.ReadTimeout. The socket will wait till x seconds (as configured in the parameter) and then times out.

After configuring these two parameters, now my WebLogic server is free from any stuck threads. However, as I mentioned above, this should be used as a workaround and you should try to fix the real issue - network latency or the response time of the remote operation.

Thank for reading my post and please leave your comments or any further questions here.

How to use Percentile for subset of EXCEL data without using Pivot table

I thought twice before writing this post as it is not my usual stuff - Enterprise architecture/Integration/SOA/Web services. When I was analyzing the access logs of WebLogic application servers for a performance engineering project for an African customer, I had to spend some time on the excel. I wanted to share my experience as a useful tip here as it will be useful to someone in the globe.

I have been a big fan of Pivot table & Pivot chart for analyzing large set of records. Almost all the times,  my requirements - calculate minimum value, maximum value, average value, count of problematic/badly performing URLs - were same and done very easily using Pivot table. But this time, I got a new requirement - calculate the 90th percentile in addition to min, max, average and count statistics. Initially I thought it was a very easy task but believe me it took more than one full day.

See below sample records. (My original data was very different. For easy understanding, I am giving sample data here)



I want to calculate the 90% percentile for

1. Both animals
2. Only for Lion
3. Only for Tiger

Pivot table supports, by default, calculating min, max and average values but not percentile. The "percentile" function in Excel can be used to find 90th percentile of age for all kinds of animals (i.e., Tiger plus Lion) as mentioned below:

=PERCENTILE.INC($D$7:$D$16, 0.9)

Note: "C7 to C16" contains the kind and "D7 to D16" contains the age.

Next, we have to find the 90th percentile for Lion and Tiger separately. We have to extract the subset of given raw data and then apply percentile function. I choose to use "IF" function to extract the subset (i.e., records that belong only to "Lion" or "Tiger"). Now, my formule will look like below:

=PERCENTILE.INC(IF($C$7:$C$16="Lion",$D$7:$D$16), 0.9)

=PERCENTILE.INC(IF($C$7:$C$16="Tiger",$D$7:$D$16), 0.9)

Are we done? Not yet. In the result cell, I get "0" value instead of getting the expected value. This is where I actually spend most of times to resolve the issue. At last, one trick helped me - after typing the formula in the cell, instead of pressing "ENTER", we have to press "CTRL+SHIFT+ENTER". When we press "CTRL+SHIFT+ENTER", it puts a curly brace around the formula. Please see below new formule
{=PERCENTILE.INC(IF($C$7:$C$16="Lion",$D$7:$D$16), 0.9)} and {=PERCENTILE.INC(IF($C$7:$C$16="Tiger",$D$7:$D$16), 0.9)}


Now, I got the result which I expected (as given below):



There may be other way of doing this, but I wanted to share my experience. This has reduced my ongoing effort from few hours to few minutes and improved my productivity. If it saves your time too, I will be happy.