Marco's Corner

Just another Software Developer's Musings

Browsing Posts in Java

My never ending story with Tomcat and logging.  The previous posts are here and here. This version has two updates.

  1. Tomcat was still sending the System.out and System.err streams to the shell and eventually to catalina.out in the normal configuration.  The jar file now contains a life cycle listener which can be used to redirect those to syslogd as well.  Just add a line like <Listener className=”org.apache.log4j.contrib.ServerLifecycleListener” /> to the to of the server.xml after all the other <Listener> elements. The new streams will show up as [stderr] and [stdout].
  2. We use JRuby on Rails inside our Tomcat. That setup sticks sometimes many lines including ‘\n’s and terminal color codes into one logging message. The normal  SyslogAppender class will split the message based on the maximum length for syslogd. But that does create messages which are hard to read. So I created a subclass of the org.apache.log4j.net.SyslogAppender, called org.apache.log4j.net.NlSplitSyslogAppender, which splits any message on ‘\n’ and also cleans up all the terminal codes which just add clutter to the syslogd messages. Just replace the org.apache.log4j.net.SyslogAppender with org.apache.log4j.net.NlSplitSyslogAppender in your log4j.properties to play with it.

The updated jar with all the sources is mw-syslog.jar. Maybe I’ll create a github repo eventually for this. Every time I hope it’s the last change, but I come back to again and again.

As always, have fun,

Jruby and Thread Dumps

1 comment

OK, today I would like to share a little patch I was toying around with in the JRuby world.

First a little background. We run some Ruby on Rails application via JRuby in JavaEE web containers, either in Tomcat or in GlassFish. That’s all nice and good when everything is working. But we have some requests once in a while which take forever. So far nobody could find a good cause for that and it usually happens ones the server is up and running for a while:-( The JVM has a helper for situations like that: you can send a SIGQUIT to the running process and it will produce a nice thread dump for all threads. That works OK for Java since it gives you the source files and line numbers, so you can get a good idea where & what your different threads are doing. Trying to do that for JRuby, you get a nice dump of the JRuby internals, but no real useful information at the Ruby level:-(

A SIGQUIT thread dump for a mongrel setup (my dev environment) looks something like the piece below, for a Tomcat/GF setup, it would have many more threads but they would be very similar, at least the tops of them.  Look at it and try to spot, that the sleep() on the top is a sleep() I added at the first line of one of our RoR views.

~/testapp$ ~/jruby/bin/jruby -S script/server  &
[1] 8260
mw install MwSignalHandler(USR2)
=> Booting Mongrel
=> Rails 2.3.11 application starting on http://0.0.0.0:3000
** [NewRelic] NewRelic Agent Developer Mode enabled.
** [NewRelic] To view performance information, go to http://localhost:3000/newrelic
** [NewRelic] New Relic RPM Agent 2.9.5 Initialized: pid = 8260
** [NewRelic] Agent Log found in ~/testapp/log/newrelic_agent.log
=> Call with -d to detach
=> Ctrl-C to shutdown server

~/testapp$ jobs
[1]+  Running                 ~/jruby/bin/jruby -S script/server &
~/testapp$ kill -QUIT %1
2012-08-07 20:37:00
Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.1-b02 mixed mode):

"RubyThread-32: ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:285" daemon prio=10 tid=0x00007f55ac099800 nid=0x20a5 in Object.wait() [0x00007f55aa7bc000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000fe1b29f8> (a org.jruby.RubyThread)
at org.jruby.RubyThread.sleep(RubyThread.java:801)
- locked <0x00000000fe1b29f8> (a org.jruby.RubyThread)
- locked <0x00000000fe1b29f8> (a org.jruby.RubyThread)
at org.jruby.RubyKernel.sleep(RubyKernel.java:824)
at org.jruby.RubyKernel$s$0$1$sleep.call(RubyKernel$s$0$1$sleep.gen:65535)
at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:630)
at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:207)
at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:312)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:169)
at org.jruby.ast.FCallOneArgNode.interpret(FCallOneArgNode.java:36)
at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
at org.jruby.ast.EnsureNode.interpret(EnsureNode.java:96)
at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:75)
at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:212)
at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:187)
at org.jruby.RubyClass.finvoke(RubyClass.java:576)
at org.jruby.RubyBasicObject.send(RubyBasicObject.java:2772)
at org.jruby.RubyKernel.send(RubyKernel.java:2097)
at org.jruby.RubyKernel$s$send.call(RubyKernel$s$send.gen:65535)
at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:342)
at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:212)
at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:221)
at org.jruby.ast.CallTwoArgBlockNode.interpret(CallTwoArgBlockNode.java:62)
at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)
at org.jruby.runtime.InterpretedBlock.evalBlockBody(InterpretedBlock.java:374)
at org.jruby.runtime.InterpretedBlock.yield(InterpretedBlock.java:295)
at org.jruby.runtime.InterpretedBlock.yieldSpecific(InterpretedBlock.java:229)
at org.jruby.runtime.Block.yieldSpecific(Block.java:99)
at org.jruby.ast.ZYieldNode.interpret(ZYieldNode.java:25)
at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
at org.jruby.ast.EnsureNode.interpret(EnsureNode.java:96)
at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:75)
at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:212)
at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:187)
at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:322)
at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:178)
at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:187)
at org.jruby.ast.CallOneArgBlockNode.interpret(CallOneArgBlockNode.java:60)
at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:75)
at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:255)
at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:203)
at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:91)
at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:342)
at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:212)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:216)
at org.jruby.ast.FCallSpecialArgBlockPassNode.interpret(FCallSpecialArgBlockPassNode.java:40)
at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)
at org.jruby.runtime.InterpretedBlock.evalBlockBody(InterpretedBlock.java:374)
at org.jruby.runtime.InterpretedBlock.yield(InterpretedBlock.java:295)
at org.jruby.runtime.InterpretedBlock.yieldSpecific(InterpretedBlock.java:229)
at org.jruby.runtime.Block.yieldSpecific(Block.java:99)
at rubyjit.trace_method_execution_with_scope_78ABF05203AC3E33573FAF5CB6B4659DC346B6C3.chained_2_ensure_1$RUBY$__ensure__(~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:62)
at rubyjit.trace_method_execution_with_scope_78ABF05203AC3E33573FAF5CB6B4659DC346B6C3.__file__(~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:61)
at rubyjit.trace_method_execution_with_scope_78ABF05203AC3E33573FAF5CB6B4659DC346B6C3.__file__(~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:87)
at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:272)
at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:80)
at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:89)
at org.jruby.ast.CallManyArgsBlockNode.interpret(CallManyArgsBlockNode.java:59)
....

As you can see, it’s mostly AST handling in the JRuby runtime but not much useful. I actually took only the top of the dump, it’s about 1000 lines long, but I wanted to show that it sometimes has some references to JITed methods which can give you a hint about a location. But even that’s not really granular:-(

But JRuby can create nice Ruby level stack traces when it hits a `Ruby level exception’. So the runtime system has to keep all that information somewhere. After that realisation, I started looking at the OpenJDK and the JRuby sources.

I looked at OpenJDK to see if there is any possibility to combine the Java and JRuby dumps somehow. Either as an additional section or somehow intermixed. But I could not find any way to do that, the SIGQUIT handling is completely done at the C/C++ level without an easy way to extend it:-( Even chaining signal handlers for the SIGQUIT does not seem to be possible, at least not in the OpenJDK and the Oracle JDK. So I had to use a different way, I decided to use SIGUSR2 for now, but that could easily be switched in the patch.

The excursion into JRuby was to find where it kept it’s stack information and see if there is a way to print it whenever I wanted to. Most of it is handled in ThreadContext.java and I found a reasonably usable spot for my hack in RubyThread.java. So when I now send a SIGUSR2 to my patched jruby, I get a Ruby level tread dump for all Ruby threads.

For the same sleep(), that looks something like

~/testapp$ kill -USR2 %1
========== MwSignalHandler.signalAction(USR2) ==========
========== RubyThread = Thread[main,5,main]
========== ThreadContext= org.jruby.runtime.ThreadContext@4b0fc9d1
#<Class:0xea211cf>#run at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/handler/mongrel.rb:37
#<Class:0x10cbd8dc>#(root) at ~/testapp/vendor/bundle/jruby/1.8/gems/rails-2.3.11/lib/commands/server.rb:110
========== RubyThread = Thread[RubyThread-1: ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/stats_engine.rb:29,5,main]
========== ThreadContext= org.jruby.runtime.ThreadContext@798aded6
NewRelic::Agent::StatsEngine#spawn_sampler_thread at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/stats_engine.rb:31
========== RubyThread = Thread[Thread-2,5,]
========== RubyThread = Thread[Thread-3,5,]
========== RubyThread = Thread[RubyThread-12: ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:268,5,main]
========== ThreadContext= org.jruby.runtime.ThreadContext@c2bf1f1
Mongrel::HttpServer#run at ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:271
========== RubyThread = Thread[RubyThread-13: ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:285,5,main]
========== ThreadContext= org.jruby.runtime.ThreadContext@19190b75
ActionView::Base::CompiledTemplates#_run_erb_app47views47home47index46html46erb at ~/testapp/app/views/home/index.html.erb:0
#<Class:0x136157d8>#render at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/renderable.rb:33
ActionView::Base#with_template at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/base.rb:305
ActionView::Renderable#render at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/renderable.rb:29
#<Class:0x136157d8>#render_with_trace_View___path__Rendering at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:160
ActionView::Template#render_with_trace_View___path__Rendering at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:159
ActionView::Template#render_template at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/template.rb:204
ActionView::Base#render at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/base.rb:264
ActionView::Base#_render_with_layout at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/base.rb:347
ActionView::Base#render at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/base.rb:261
ActionController::Base#render_for_file at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:1251
ActionController::Base#render at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:935
HomeController#render_with_benchmark at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/benchmarking.rb:50
#<Class:0x669b9a30>#ms at ~/testapp/vendor/bundle/jruby/1.8/gems/activesupport-2.3.11/lib/active_support/core_ext/benchmark.rb:16
Benchmark#realtime at ~/jruby/lib/ruby/1.8/benchmark.rb:307
#<Class:0x669b9a30>#ms at ~/testapp/vendor/bundle/jruby/1.8/gems/activesupport-2.3.11/lib/active_support/core_ext/benchmark.rb:16
ActionController::Benchmarking#render_with_benchmark at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/benchmarking.rb:50
ApplicationController#render at ~/testapp/app/controllers/application_controller.rb:117
ActionController::Base#default_render at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:1327
ActionController::Base#perform_action at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:1333
ActionController::Filters::InstanceMethods#call_filters at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/filters.rb:616
ActionController::Filters::InstanceMethods#perform_action_with_filters at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/filters.rb:609
HomeController#perform_action_with_benchmark at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/benchmarking.rb:67
#<Class:0x669b9a30>#ms at ~/testapp/vendor/bundle/jruby/1.8/gems/activesupport-2.3.11/lib/active_support/core_ext/benchmark.rb:16
Benchmark#realtime at ~/jruby/lib/ruby/1.8/benchmark.rb:307
#<Class:0x669b9a30>#ms at ~/testapp/vendor/bundle/jruby/1.8/gems/activesupport-2.3.11/lib/active_support/core_ext/benchmark.rb:16
ActionController::Benchmarking#perform_action_with_benchmark at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/benchmarking.rb:67
ActionController::Rescue#perform_action_with_rescue at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/rescue.rb:159
ActionController::Flash::InstanceMethods#perform_action_with_flash at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/flash.rb:150
HomeController#perform_action_with_newrelic_trace at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:137
NewRelic::Agent::MethodTracer#trace_method_execution_with_scope at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:61
HomeController#perform_action_with_newrelic_trace at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:121
NewRelic::Agent::MethodTracer#trace_method_execution_no_scope at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:37
NewRelic::Agent::Instrumentation::ControllerInstrumentation#perform_action_with_newrelic_trace at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:116
ActionController::Base#process at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:531
ActionController::Filters::InstanceMethods#process_with_filters at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/filters.rb:605
#<Class:0xdf20541>#process at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:390
#<Class:0xdf20541>#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:385
ActionController::Routing::RouteSet#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/routing/route_set.rb:437
ActionController::Dispatcher#dispatch at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/dispatcher.rb:86
ActionController::Dispatcher#_call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/dispatcher.rb:120
ActionController::Dispatcher#build_middleware_stack at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/dispatcher.rb:129
ActionController::StringCoercion#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/string_coercion.rb:24
Rack::Head#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/head.rb:8
Rack::MethodOverride#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/methodoverride.rb:23
ActionController::ParamsParser#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/params_parser.rb:14
ActionController::Session::AbstractStore#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/session/abstract_store.rb:176
ActiveRecord::QueryCache#call at ~/testapp/vendor/bundle/jruby/1.8/gems/activerecord-2.3.11/lib/active_record/query_cache.rb:28
ActiveRecord::ConnectionAdapters::QueryCache#cache at ~/testapp/vendor/bundle/jruby/1.8/gems/activerecord-2.3.11/lib/active_record/connection_adapters/abstract/query_cache.rb:33
ActiveRecord::QueryCache::ClassMethods#cache at ~/testapp/vendor/bundle/jruby/1.8/gems/activerecord-2.3.11/lib/active_record/query_cache.rb:8
ActiveRecord::QueryCache#call at ~/testapp/vendor/bundle/jruby/1.8/gems/activerecord-2.3.11/lib/active_record/query_cache.rb:27
ActiveRecord::ConnectionAdapters::ConnectionManagement#call at ~/testapp/vendor/bundle/jruby/1.8/gems/activerecord-2.3.11/lib/active_record/connection_adapters/abstract/connection_pool.rb:360
ActionController::Failsafe#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/failsafe.rb:25
Rack::Lock#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/lock.rb:10
Rack::Lock#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/lock.rb:10
ActionController::Dispatcher#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/dispatcher.rb:113
#<Class:0x56683a8d>#run at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/reloader.rb:33
ActionController::Dispatcher#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/dispatcher.rb:107
Rails::Rack::Static#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rails-2.3.11/lib/rails/rack/static.rb:30
Rack::URLMap#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/urlmap.rb:48
Rack::URLMap#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/urlmap.rb:40
Rails::Rack::LogTailer#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rails-2.3.11/lib/rails/rack/log_tailer.rb:16
Rack::ContentLength#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/content_length.rb:12
Rack::Chunked#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/chunked.rb:14
Rack::Handler::Mongrel#process at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/handler/mongrel.rb:66
Mongrel::HttpServer#process_client at ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:158
Mongrel::HttpServer#process_client at ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:157
Mongrel::HttpServer#run at ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:284

The line numbers seem to be 0 based but that’s how JRuby stores the info internally. I did not really change that. I did some checks that it seems to work as expected.

I did not do the complete github fork & patch routine yet, if I find the need to change this more in the future, I probably will do that. But for now, jruby-1.6.7.2-SigUSR2Patch.tar is my little patch. It contains the changed source and all the class files for org.jruby.RubyThread.java based on JRuby 1.6.7.2. That source file did not change since 1.6.5, so I don’t expect many changes in the next couple of iterations. Applying the changes (for tests) is pretty easy, just stick all the *.class files into the jruby.jar to replace the originals.

But as always, this is a hack, use at your own risk!! But have fun trying it out;-)

Ok, more things I don’t like about Apache Tomcat😉 We have a web application which wants to be installed into the root context. But that means that the normal /manager webapp would either show up in it’s `directory-space’ or we would not be able to use it at all 🙁 We have an Apache web server in front of the Tomcat so we could try to filter certain paths, but that creates extra interdependencies which I would like to avoid in `security critical’ areas.

The normal setup, which works for things like zapcat or Jolokia, is to create a new service in the same server, which listens on a different port and use that. Unfortunately, the default ManagerServlet class can not handle such a setup.

So I took the org.apache.catalina.manager.ManagerServlet as base and extended it so that it understands two additional request parameter service & host. If just one of them is used, the other uses a sensible default. I could not really sub-class the original class, because the changes were all over the place 🙁

So with a server.xml specifying two services “Catalina, listening on 8080” and “Management, listening on 8081”, I can list the deployed applications on both from the “Management” service:

root@box:/tmp# curl 'http://root:root@box:8081/manager/list         
OK - Listed applications for virtual host localhost
/manager:running:0:manager
/j4p:running:0:j4p
/host-manager:running:0:host-manager
root@box:/tmp# curl 'http://root:root@box:8081/manager/list?service=Catalina
OK - Listed applications for virtual host localhost
/:running:0:ROOT
root@box:/tmp# curl 'http://root:root@box:8081/manager/list?service=Management
OK - Listed applications for virtual host localhost
/manager:running:0:manager
/j4p:running:0:j4p
/host-manager:running:0:host-manager

That works the same way for deploy & undeploy as well 😉 So now my root context application is happy and all the `management apps’ can be accessed on a different port with different  access parameters 😉

The source & class for Tomcat 6.0.35 is here, in this little  mw-manager.jar. After reading the source 😉 , just drop it into your tomcat lib directory, adapt your manager-application’s web.xml to use the AllManagerServlet instead of the default ManagerServlet, and have fun 😉

The manager application allows to control the tomcat installation. So please be careful!! While I think, the little new servlet works for me, make sure it does the things you expect!! Or use it as example for your own excursions into the Tomcat code 😉

As always, have fun exploring 😉

— Marco

After I got the access logs for our Tomcat‘s to syslogd (see the entry below), I found that the Solaris syslogd can not handle the the RFC-5424 header format:-( So the info in that section was not really useful for us.

That brought up a new problem, I needed to include the process ID in the log records. So I updated my little extension jar to handle an extra %P format specifier for the SyslogAccessLogValve class.

The normal log4j 1.2 also has no real way to include the process ID in the records. So I added a little org.apache.log4j.PidPatternLayout which handles the %P in addition to the normal PatternLayout.

The new jar file with both the sources and all the classes is here;-) mw2.jar

I hope it helps some people. Have fun playing,
— Marco

Update:  Here is a new version of the jar: mw3.jar which hopefully removes the StringManager dependency for Tomcat7. I still did not test it with Tomcat7!!

Update: Next post in what becomes a series?!

OK, I searched the WWW far and wide, but I could not really find a good solution how to send the access log from Apache Tomcat to a syslogd:-( So I checked the source;-) and there were at least more than the default AccessLogValve.java implementation. There was even one for logging to a DB. But not for syslogd:-(

I don’t normally do much in Java any more, but I still understand it;-) So I started to look into what it would take to create a new Valve to do what I wanted. It did turn out to be not that hard, especially with the help of the Apache log4j SyslogAppender.java and friends;-)

This little jar contains my shiny new SyslogAccessLogValve as source & class. It was compiled against Apache Tomcat 6.0.35, but I don’t think it would be a big problem to port it to version 7. The new class lives in the same package as all the others valves. But keep in mind that it’s NOT an official apache.org source!!

Drop the jar into CATALINA_BASE/lib and configure the new valve as any other AccessLogValve:

    <Valve className="org.apache.catalina.valves.SyslogAccessLogValve"
        hostname="localhost"
        facility="local6"
        pattern="common"
        resolveHosts="false"/>

This will try to send the messages to the syslogd running on localhost and use the LOCAL6 facility. Since this class is a subclass of the orginal AccessLogValve, the pattern can contain the same elements as it’s superclass. I just used “common” for my tests so far, but the formatting is dome by the superclass;-)

And now the final output from syslogd, actually rsyslogd on my Linux system;-)

Jun 12 20:32:16 feather4 http-8080-1[10763] 0:0:0:0:0:0:0:1 - - [12/Jun/2012:20:32:16 -0700] "GET / HTTP/1.1" 200 7777
Jun 12 20:32:16 feather4 http-8080-1[10763] 0:0:0:0:0:0:0:1 - - [12/Jun/2012:20:32:16 -0700] "GET /tomcat.gif HTTP/1.1" 200 1934
Jun 12 20:32:16 feather4 http-8080-2[10763] 0:0:0:0:0:0:0:1 - - [12/Jun/2012:20:32:16 -0700] "GET /asf-logo-wide.gif HTTP/1.1" 200 5866
Jun 12 20:32:16 feather4 http-8080-2[10763] 0:0:0:0:0:0:0:1 - - [12/Jun/2012:20:32:16 -0700] "GET /tomcat-power.gif HTTP/1.1" 200 2324

Those are the four accesses when a browser hits the Apache Tomcat default home page.

I don’t know if that’s helpful for others, but since I saw a couple of places where the same question came up, it might be. In that case, have fun with it;-)

Update: Since this still seems to be found quite often, there is an update for this post in the next entry!

I did not post here for a long time. One of the reasons was, that I was not really able to say too much about what we were trying to build. But now “Project Kenai” has made it to the public beta. So I can say that I was working on it for the last 18 or so month;-)

We run JRuby inside Glassfish and that’s why I was interested in GF again. We have all kinds of servers running and we would like to consolidate all of the log information for easier handling. Most of the native Unix daemons don’t have a problem with that, they can all log their information via syslogd. Glassfish claims to be able to do that as well. But I would currently say, it’s more a claim than reality in the official builds:-(

We tried to let GF log via syslogd and found very quickly two problems:

  • You can kill GF (the running JVM) with the right kind of log messages:-( Off course, it took us only days  to hit that  problem , figuring  out the reason was a little bit harder. But I did it and filed issue 6291 but not to much moved on it:-(
  • If you want the access logs also via syslogd, you’re out of luck:-( That is hard-coded to to go to files.

But GF is OpenSource, right? I had already looked at the code to find the reason for the 6291 bug. Could I change it so that it would do what I wanted? It turns out that it was not too hard to get a first version working;-)

It’s probably not perfect and you can clearly see the steps I took but the two little patches below will:

  • Fix the bug, very important;-)
  • Allow to change the syslog facility to values other than LOG_DAEMON via an environment variable called GF_LOG_FACILITY. (Up to that point, I staid within the native code;-)
  • Allow for the access logs to be written to the syslogd as well. To do that, I check for a magic ‘::’ at the beginning of the ‘accesslog’ property of the ‘virtual-server’ elements in the domain.xml. That property is supposed to be a directory where GF would create the access log files. I thought, not too many directories would start with ‘::’ 😉

My first tests were successful. Now we have to decide if we want to use a patched version of GF.

The two patches are against the modules appserv-core and appserv-native.

For appserv-core, I followed the normal build instructions from the wiki and used the TSJSAS91_FCS_BRANCH tag. (I did a complete build but I don’t think that would be needed) I then transplanted the two interesting class files into a copy (appserv-rt.jar) of our official GF version for testing.

I did not get the appserv-native module via the normal CVS/maven checkout. But since I found the problematic file before with the Fisheye in the SVN tree, I was able to check that module out via SVN. The v3 build instructions help to find the right SVN tree, but we are still interested in v2 here;-) It’s native code, so if somebody wants to try that, you will need the Sun C compilers etc.

After building and replacing the libutilforsyslog.so, everything seem to be working as expected and I can enjoy my logs via the normal syslogd setup;-) Below are both, the normal server log and the access log directed to LOG_LOCAL6:

Oct 10 21:22:58 kenaidev13 SJSAS81_server.log: [ID 702911 local6.info] [#|2008-10-10T21:22:58.934-0700|INFO| \
sun-appserver9.1|javax.enterprise.system.container.web|_ThreadID=17;_ThreadName=httpSSLWorkerThread-8080-0;| \
PWC1412: WebModule[] ServletContext.log():
Oct 10 21:22:58 kenaidev13 Processing HomeController#index (for 127.0.0.1 at 2008-10-10 21:22:58) [GET]
Oct 10 21:22:58 kenaidev13   Session ID: 376348f6751afdd3c1220777a0ee15ca
Oct 10 21:22:58 kenaidev13   Parameters: {"controller"=>"home", "action"=>"index"}
Oct 10 21:22:58 kenaidev13 Rendering template within layouts/kenai.com
Oct 10 21:22:58 kenaidev13 Rendering home/index
Oct 10 21:22:58 kenaidev13 Completed in 0.34706 (2 reqs/sec) | Rendering: 0.30226 (87%) | DB: 0.00000 (0%) | 200 OK [http://localhost/]
Oct 10 21:22:58 kenaidev13 |#]
Oct 10 21:22:58 kenaidev13 [9374]: [ID 702911 local6.info] "127.0.0.1" "NULL-AUTH-USER" "10/Oct/2008:21:22:58 -0800" \
"GET / HTTP/1.0" 200 14058

If you made it all the way here, those are the two little patches:  appserv-core.patch & appserv-native.patch.  They are in no way official  or fully tested. But they show that somebody can quickly add functionality if needed;-)

Have fun & I hope I’ll write more often again;-)
— Marco

JavaOne FlyerUsually I try to stay out of the big announcements. But an email today caught my eye. You know, all those high-gloss flyers you get for diverse expos and conferences are using a lot of resources. Sun decided to to the first round for this years JavaOne online-only. If you have read some postings here, you will know that I really like that idea.

Here are the estimated resource savings:

"By producing this piece virtually, the Eco group has calculated the savings Sun has made:
Savings from not sending DM1 this year
-Assuming (based on last year) DM1 is equivalent to 2.5 pages of 0% recycled copy paper
-Total paper saved = 4.63 tons
-Greenhouse Gases reduced (CO2 equivalents) = 13  tons (26,297 lbs)
-Reduction in wood use = 13 tons
-# of trees saved (assuming 1 tree makes 16.67 reams of copy paper or 8,333.3 sheets) = 111
-Reduction in wastewater (and associated water pollution) = 78,616 gallons *(equivalent to 838K cans of soda)*
-Reduction in solid waste (stuff sent to landfills)  = 5.1 tons"

I think that’s a good start. So please head on over to the JavaOne web site to read more about  the upcoming conference.

 

We finally released the Visual Web Pack for NetBeans 5.5;-) So I might actually write a couple of more entries here again.

Some people see problems when they try to take a project from the VWP TP and open/build it with the final version of VWP. Something like:

I installed the new version of VWP but when I want to use my
previous project it shows below error:

C:\TP_Project\nbproject\build-impl.xml:419: Warning: Could not find file C:\TP_Project\${libs.woodstock-components.classpath.libfile.6} to copy.
BUILD FAILED (total time: 1 second)

The problem is that the libraries for the components have changed. Normally that should be handled automatically on project open when the project properties are synchronized with the values from the IDE. But when there are no other changes, to the IDE, the regeneration of the nbproject/build-impl.xml might not happen.

So when you see this problem while building/deploying a TP project, do the following:

  • Close the project
  • Remove the nbproject/build-impl.xml file from the project.
  • Reopen the project and work with it.

The reopen will regenerate the nbproject/build-impl.xml with the right information.

I hope this is helpfull;-)

Thanks,

— Marco

Long time nothing on this blog. Sorry about that. But here I come again;-)

I started playing with NB 6 on top of the Java SE 6 RC builds. And as always I’m not using the default configuration. So I ran into an interesting problem. The NB IDE was not able to open an external browser on my Kubuntu 6.06 system:-(

That worked fine with all the NB 5.5 builds I played with, but as it turns out, NB 6 makes use of the new java.awk.Desktop classes when it’s running on a newer JDK. But that class only throws IOExceptions when it isn’t able to handle the browse() action.

So strace is your friend, and a few minutes later, I had:

[pid 15878] execve("/export/home/marcow/bin/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/usr/local/sbin/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/usr/local/bin/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/usr/sbin/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/usr/bin/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/sbin/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/bin/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/usr/bin/X11/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/usr/games/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/export/home/marcow/usr/vspms/bin/linux/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/export/home/marcow/usr/vspms/bin/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/opt/Forte/teamware/bin/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/export/home/marcow/usr/vspms/bin/linux/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/export/home/marcow/usr/vspms/bin/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)
[pid 15878] execve("/opt/Forte/teamware/bin/gnome-www-browser", ["gnome-www-browser", "http://www.sun.com"], [/* 46 vars */]) = -1 ENOENT (No such file or directory)

OK, once you know what the system is looking for, it’s easy to fix;-) If your path does not contain a gnome-www-browser, create one via a simple symlink.

Maybe this helps some people.

Have fun,
— Marco