webtier@glassfish.java.net

Re: [webtier] "Interrupting Idle Thread" error with RoR app using Glassfish v3 gem

From: Vivek Pandey <Vivek.Pandey_at_Sun.COM>
Date: Mon, 23 Nov 2009 17:23:29 -0800

Mark,

Looks like you need someway to renew database connection. Not sure if
its an issue in the jdbc MySQL adapter or the jdbc-mysql gem. Since
firewall is causing idle connection termination so what you are looking
for is for someway something to reconnect. Nick Sieger is the author of
the gem. Maybe he can suggest how to renew a new connection. Try
posting your findings to user_at_jruby.codehaus.org, maybe someone ran in
to such issue before and might have some suggestions.

-vivek.

Mark Westling wrote:
> Hi Vivek,
>
> I noticed something interesting in the production.log file. I'd said
> before that the RoR application froze after a lengthy idle time, and
> it seems this isn't correct. What's happening is that the first
> request after idle takes a very long time to execute. Here's the log:
>
> Nov 24, 2009 8:12:47 AM com.sun.grizzly.config.GrizzlyServiceListener
> WARNING: Interrupting idle Thread: http80-WorkerThread(3)
> Nov 24, 2009 8:20:07 AM com.sun.grizzly.config.GrizzlyServiceListener
> INFO:
>
> Processing HomeController#index (for at 2009-11-24 08:20:07) [GET]
> Redirected to http://202.140.96.154/user_sessions/new
> Filter chain halted as [:require_user] rendered_or_redirected.
> Completed in 11ms (DB: 1) | 302 Found [http://202.140.96.154/]
>
> Nov 24, 2009 8:23:12 AM com.sun.grizzly.config.GrizzlyServiceListener
> INFO:
>
> Processing HomeController#index (for at 2009-11-24 08:07:46) [GET]
> Rendering template within layouts/application
> Rendering home/index
> Completed in 925705ms (View: 11, DB: 925676) | 200 OK
> [http://202.140.96.154/]
>
> Note the DB time of 925s. The customer has advised me that all
> database queries go through a firewall that terminates idle
> connections but I didn't think anything of this, figuring that I'd
> either see a DB connection error or there would be a reconnect that
> would automatically fix it.
>
> I did a thread dump during this 925s wait period and found this thread:
>
> "http80-WorkerThread(3)" daemon prio=10 tid=0xb31cf400 nid=0x5d25
> runnable [0xb2ff1000]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> at
> com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
> at
> com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
> at
> com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
> - locked <0x760a3548> (a com.mysql.jdbc.util.ReadAheadInputStream)
> at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1910)
> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2304)
> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2803)
> at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1573)
> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
> at com.mysql.jdbc.Connection.execSQL(Connection.java:3170)
> - locked <0x7609fd38> (a java.lang.Object)
> at com.mysql.jdbc.Connection.execSQL(Connection.java:3099)
> at com.mysql.jdbc.Statement.executeQuery(Statement.java:1169)
> - locked <0x7609fd38> (a java.lang.Object)
> at
> jdbc_adapter.RubyJdbcConnection$6.call(RubyJdbcConnection.java:254)
> at
> jdbc_adapter.RubyJdbcConnection.withConnectionAndRetry(RubyJdbcConnection.java:1072)
> at
> jdbc_adapter.RubyJdbcConnection.executeQuery(RubyJdbcConnection.java:247)
> at
> jdbc_adapter.RubyJdbcConnection.execute_query(RubyJdbcConnection.java:234)
> at
> jdbc_adapter.RubyJdbcConnection$i_method_multi$RUBYINVOKER$execute_query.call(jdbc_adapter/RubyJdbcConnection$i_method_multi$RUBYINVOKER$execute_query.gen)
> at
> org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:310)
> at
> org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:149)
> at
> ruby.jit.ruby.usr.local.jruby_minus_1_dot_4_dot_0.lib.ruby.gems.$1_dot_8.gems.activerecord_minus_jdbc_minus_adapter_minus_0_dot_9_dot_2.lib.active_record.connection_adapters.jdbc_adapter._execute9030225_18734324.__file__(jdbc_adapter.rb:569)
> at
> ruby.jit.ruby.usr.local.jruby_minus_1_dot_4_dot_0.lib.ruby.gems.$1_dot_8.gems.activerecord_minus_jdbc_minus_adapter_minus_0_dot_9_dot_2.lib.active_record.connection_adapters.jdbc_adapter._execute9030225_18734324.__file__(jdbc_adapter.rb)
> at
> org.jruby.ast.executable.AbstractScript.__file__(AbstractScript.java:51)
> at
> org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:187)
> at
> org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:330)
> at
> org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:189)
> at
> ruby.jit.ruby.usr.local.jruby_minus_1_dot_4_dot_0.lib.ruby.gems.$1_dot_8.gems.activerecord_minus_jdbc_minus_adapter_minus_0_dot_9_dot_2.lib.active_record.connection_adapters.jdbc_adapter.execute5048333_18734324.block_0$RUBY$__block__(jdbc_adapter.rb:560)
> [...]
>
> Here are my MySQL-related gems:
>
> activerecord-jdbc-adapter (0.9.2)
> activerecord-jdbcmysql-adapter (0.9.2)
> jdbc-mysql (5.0.4)
>
> And here's a snippet from database.yml:
>
> production:
> adapter: <%= jdbc %>mysql
> encoding: utf8
> database: myapp_production
> host: 172.0.0.223
> username: myacct
> password: mypass
> reconnect: true
> pool: 100
>
> Any suggestions?
>
> Thanks,
> Mark
>
>
> On Mon, Nov 16, 2009 at 2:51 PM, Vivek Pandey <Vivek.Pandey_at_sun.com
> <mailto:Vivek.Pandey_at_sun.com>> wrote:
>
> Mark Westling wrote:
>
> Hi Vivek,
>
> I've opened an issue on RubyForge as you suggested. gfrake
> didn't help; in fact, I can reproduce the errors using a newly
> created rails app. So, I suspect it's some kind of
> configuration problem. (I did check and I'm using rubygem 1.3.5).
>
> I just posted on your bug. I see you are using jdk 6 u18 EA. The
> exception is form xml parser which is part of jdk 6. Can you try
> with jdk6 u17.
>
> Going back to the original problem (connection freezing after
> a long idle), should I paste a thread dump (from 0.9.5,
> obviously) here on the list or open another issue?
>
> You can paste it here.
>
> -vivek.
>
> Thanks!
> Mark
>
>
>
> On Thu, Nov 12, 2009 at 2:13 PM, Vivek Pandey
> <Vivek.Pandey_at_sun.com <mailto:Vivek.Pandey_at_sun.com>
> <mailto:Vivek.Pandey_at_sun.com <mailto:Vivek.Pandey_at_sun.com>>>
> wrote:
>
> I double checked the tests and see everything working just
> fine.
>
> I am not doubting this as an issue at your end but will
> mention it
> anyway, since 0.9.6.dev has (dev) suffix, which gem treats as
> pre-release version. There are issues using the prerelease
> versions with rubygem < 1.3.5. So I would recommend doing
>
> gem update --system
>
> This will update your rubygem to 1.3.5 and 0.9.6.dev after
> installed will be identified as the latest version.
>
> You can open an issue ticket at
> http://rubyforge.org/projects/glassfishgem/. Also provide
> steps on
> how I can reproduce it.
>
> -vivek.
>
>
> Vivek Pandey wrote:
>
> Hmm. Our tests are running fine with this gem. I guess
> I know
> what might be happening.
>
> Can you try
>
> $ gfrake clean
>
> and then run your application. This new glassfish gem is
> supposed to cleanup previous tmp/.glassfish left from
> previous
> gem run maybe there is some bug and thats what is
> causing this
> failure.
>
> I will spend some time tomorrow to investigate whats
> going on
> with daemon mode. Some resource injection seem to be
> failing.
>
> -vivek.
>
> Mark Westling wrote:
>
> Thanks Vivek, I installed the build#120 version of
> the gem
> (0.9.6.dev) but now I'm running into other problems.
>
> When I set the glassfish.yml configuration to run in
> daemon mode (enable: true), I get the following in the
> production.log file:
>
> Nov 12, 2009 4:05:53 AM
> com.sun.enterprise.v3.server.SystemTasks
> setSystemPropertiesFromEnv
> SEVERE: cannot determine host name, will use localhost
> exclusively
> java.net.UnknownHostException:
> mobileadapp02.myclient-domain.com
> <http://mobileadapp02.myclient-domain.com>
> <http://mobileadapp02.myclient-domain.com>
> <http://mobileadapp02.myclient-domain.com>:
> mobileadapp02.
> myclient-domain.com <http://myclient-domain.com>
> <http://myclient-domain.com>
> <http://myclient-domain.com>
> at
>
> java.net.InetAddress.getLocalHost(InetAddress.java:1353)
> at
>
> com.sun.enterprise.util.net.NetUtils.getCanonicalHostName(NetUtils.java:95)
>
> at
>
> com.sun.enterprise.v3.server.SystemTasks.setSystemPropertiesFromEnv(SystemTasks.java:152)
>
> [...]
> at org.jruby.Main.run(Main.java:117)
> at org.jruby.Main.main(Main.java:97)
> Nov 12, 2009 4:24:35 AM
> com.sun.enterprise.v3.server.AppServerStartup run
> INFO: GlassFish v3 startup time : Embedded(200ms)
> startup
> services(161ms) total(361ms)
> Nov 12, 2009 4:24:35 AM AppServerStartup run
> INFO: [Thread[GlassFish Kernel Main Thread,5,main]]
> started
> Nov 12, 2009 4:24:35 AM
> org.hibernate.validator.util.Version <clinit>
> INFO: Hibernate Validator null
> Nov 12, 2009 4:24:35 AM
>
> com.sun.enterprise.v3.services.impl.GrizzlyProxy$2$1 onReady
> INFO: Grizzly Framework 1.9.18-e started in: 81ms
> listening on port 80
> Nov 12, 2009 4:24:35 AM
> com.sun.enterprise.v3.server.ApplicationLifecycle
> startContainers
> SEVERE: Cannot start container jruby
> java.lang.NullPointerException
> ser.java:104)
> at
>
> org.glassfish.scripting.jruby.JRubyContainer.postConstruct(JRubyContainer.java:97)
>
> at
>
> com.sun.hk2.component.AbstractWombImpl.inject(AbstractWombImpl.java:174)
> at
>
> com.sun.hk2.component.ConstructorWomb$1.run(ConstructorWomb.java:87)
> at
> java.security.AccessController.doPrivileged(Native
> Method)
> at
>
> com.sun.hk2.component.ConstructorWomb.initialize(ConstructorWomb.java:84)
>
> [...]
> at org.jruby.Main.run(Main.java:272)
> at org.jruby.Main.run(Main.java:117)
> at org.jruby.Main.main(Main.java:97)
> Nov 12, 2009 4:24:35 AM
> org.glassfish.api.ActionReport failure
> SEVERE: Aborting, Failed to start container
> org.glassfish.scripting.jruby.JRubyContainer
> Nov 12, 2009 4:24:35 AM
> org.glassfish.api.ActionReport failure
> SEVERE: Exception while deploying the app
> java.lang.Exception: Aborting, Failed to start
> container
> org.glassfish.scripting.jruby.JRubyContainer
> at
>
> com.sun.enterprise.v3.server.ApplicationLifecycle.setupContainerInfos(ApplicationLifecycle.java:448)
>
> at
>
> com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:246)
>
> at
>
> org.glassfish.kernel.embedded.EmbeddedDeployerImpl.deploy(EmbeddedDeployerImpl.java:206)
>
> at
>
> org.glassfish.kernel.embedded.EmbeddedDeployerImpl.deploy(EmbeddedDeployerImpl.java:146)
>
> at
>
> org.glassfish.scripting.gem.GlassFishMain.startGlassFishEmbedded(GlassFishMain.java:145)
>
> [...]
>
>
> If I change it to non-daemon mode (enable: false),
> I get
> the following on the console:
>
> [root_at_mobileadapp02 sched2]# jruby -S glassfish
> Parsing config file:
> /usr/local/sigma/sched2/config/glassfish.yml
> Starting GlassFish server at: 0.0.0.0:80
> <http://0.0.0.0:80>
> <http://0.0.0.0:80> <http://0.0.0.0:80> in production
>
> environment...
> Writing log messages to:
> /usr/local/sigma/sched2/log/production.log.
> Press Ctrl+C to stop.
> java.lang.UnsupportedOperationException: Cannot create
> XMLStreamReader or XMLEventReader from a
> javax.xml.transform.stream.StreamSource
> at
>
> com.sun.xml.internal.stream.XMLInputFactoryImpl.jaxpSourcetoXMLInputSource(XMLInputFactoryImpl.java:285)
>
> at
>
> com.sun.xml.internal.stream.XMLInputFactoryImpl.createXMLStreamReader(XMLInputFactoryImpl.java:145)
>
> at
>
> org.jvnet.hk2.config.ConfigParser.parse(ConfigParser.java:102)
> at
>
> org.glassfish.kernel.config.DefaultConfigParser$2.run(DefaultConfigParser.java:93)
>
> [...]
>
>
> Any suggestions?
>
> Thanks,
> Mark
>
>
> On Wed, Nov 11, 2009 at 9:46 AM, Vivek Pandey
> <Vivek.Pandey_at_sun.com <mailto:Vivek.Pandey_at_sun.com>
> <mailto:Vivek.Pandey_at_sun.com <mailto:Vivek.Pandey_at_sun.com>>
> <mailto:Vivek.Pandey_at_sun.com
> <mailto:Vivek.Pandey_at_sun.com>
> <mailto:Vivek.Pandey_at_sun.com
> <mailto:Vivek.Pandey_at_sun.com>>>> wrote:
>
> Mark,
>
> Just looking at the warning message I can say what
> really might be
> going on. Perhaps someone from grizzly team can
> comment
> on this
> particular issue.
>
> In the meantime can you give the latest
> glassfish gem (not
> released yet) a try? It will be released soon after
> more testing
> but it has latest stable Grizzly and glassfish v3
> kernel bits. I
> think its worth a try. Get build#120 from
>
> http://hudson.glassfish.org/job/glassfish-gem-build/.
>
> If the latest gem does not fix your problem, can you
> send the
> thread dump? kill -QUIT pid or ctrl + \
>
> -vivek.
>
>
>
> Mark Westling wrote:
>
> I'm running my Rails project using the
> Glassfish v3
> gem and if
> there's no activity for an hour or two
> hours, the
> next request
> hangs and logs the following error:
>
> Nov 11, 2009 3:15:44 AM
> com.sun.grizzly.config.GrizzlyServiceListener
> WARNING: Interrupting idle Thread:
> http80-WorkerThread(0)
>
> I'm using the default parameters in the
> glassfish.yml
> configuration file. This occurs in both
> daemon and
> non-daemon
> mode. The only unusual thing I might be doing is
> creating (and
> closing) several processing threads during some
> requests to
> take advantage of multiple cores for lengthy
> computations, but
> the problem seems to occur even if I don't
> run any
> thread-creation processes after a restart. In
> other words, I
> can restart glassfish, wait a few hours with no
> requests, and
> see the same error.
>
> Configuration:
> jruby 1.4.0 (ruby 1.8.7 patchlevel 174)
> (2009-11-02
> 69fbfa3)
> (Java HotSpot(TM) Client VM 1.6.0_18-ea)
> [i386-java]
> rails 2.3.3
> glassfish gem 0.9.5
> database adapter: jdbcmysql
> Linux version 2.6.18-164.el5PAE
> (mockbuild_at_x86-002.build.bos.redhat.com
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com>
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com>>
>
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com>
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com>>>
>
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com>
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com>>
>
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com>
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com
> <mailto:mockbuild_at_x86-002.build.bos.redhat.com>>>>) (gcc
> version
> 4.1.2 20080704 (Red Hat 4.1.2-46)) #1 SMP
>
> Any suggestions?
>
> --Mark
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail:
> webtier-unsubscribe_at_glassfish.dev.java.net
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>>
>
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>>>
> For additional commands, e-mail:
> webtier-help_at_glassfish.dev.java.net
> <mailto:webtier-help_at_glassfish.dev.java.net>
> <mailto:webtier-help_at_glassfish.dev.java.net
> <mailto:webtier-help_at_glassfish.dev.java.net>>
> <mailto:webtier-help_at_glassfish.dev.java.net
> <mailto:webtier-help_at_glassfish.dev.java.net>
> <mailto:webtier-help_at_glassfish.dev.java.net
> <mailto:webtier-help_at_glassfish.dev.java.net>>>
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail:
> webtier-unsubscribe_at_glassfish.dev.java.net
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>>
> For additional commands, e-mail:
> webtier-help_at_glassfish.dev.java.net
> <mailto:webtier-help_at_glassfish.dev.java.net>
> <mailto:webtier-help_at_glassfish.dev.java.net
> <mailto:webtier-help_at_glassfish.dev.java.net>>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail:
> webtier-unsubscribe_at_glassfish.dev.java.net
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>>
> For additional commands, e-mail:
> webtier-help_at_glassfish.dev.java.net
> <mailto:webtier-help_at_glassfish.dev.java.net>
> <mailto:webtier-help_at_glassfish.dev.java.net
> <mailto:webtier-help_at_glassfish.dev.java.net>>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: webtier-unsubscribe_at_glassfish.dev.java.net
> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>
> For additional commands, e-mail:
> webtier-help_at_glassfish.dev.java.net
> <mailto:webtier-help_at_glassfish.dev.java.net>
>
>