This Bugzilla instance is a read-only archive of historic NetBeans bug reports. To report a bug in NetBeans please follow the project's instructions for reporting issues.
I was debugging my (fairly) large Rails application and when I clicked on the Variables pane and tried to inspect one of my variables, the debugger quit, although the Debugger process was still running. Within the IDE Log File, there is an indication of "Received: END_DOCUMENT event" (See attached File) When this occurs, I need to manually kill the running application prior to continuing.
Created attachment 90764 [details] IDE Log File compressed
Still occurring under 200911220201 using the built-in JRuby 1.4.0
Looking at the log file, it appears that the problem may be in the debugger bridge. Here's why I believe this is the case: 1) At Time t, I view the IDE log in NB. 2) At Time t + < 1 sec. I click on the @self object in the Variables window 3) At Time T + < 1.5 sec. The Debugger disconnects from the IDE; however the debugger does not terminate. 4) At Time T + < 5 sec, I scroll down in the IDE log window and find: FINE [org.rubyforge.debugcommons.RubyDebuggerProxy]: Sending command debugger: frame 1; v i +0x3ee FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Processing: frame 1; v i +0x3ee</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Processing context: frame 1</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Selected frame no 0</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Processing context: v i +0x3ee</message> FINEST [org.rubyforge.debugcommons.Util]: Received: <variables> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received: END_DOCUMENT event FINE [org.rubyforge.debugcommons.ReadersSupport]: ReadersSupport readloop [class org.rubyforge.debugcommons.ReadersSupport command loop] successfully finished. FINEST [org.rubyforge.debugcommons.RubyDebuggerProxy]: Socket reader loop finished. Which indicates the debugger bridge thought it had spent longer than 10 seconds waiting. Possibly longer than 90 seconds (a fair timeout) when it had actually waited < 2 seconds before it terminated. This is now prohibiting me from using NB to properly debug my application.
Ignore last comment. Meant for a different issue
Yes, this indeed is likely to be a problem in debugcommons. I'll investigate.
Unfortunately I haven't yet been successful in reproducing this. To test the timeout hypothesis, can you please change the max_time variable in ruby-debug-ide-0.4.8/lib/ruby-debug/command.rb:123 (in the debug_eval method)?
I'll change the magic value to something higher (say 100 to start), but it seems like the eval() call is calling this method recursively and blowing the top of the stack. We see the @print message appear 9 times within _MILISECONDS_ of the attempt to view the variables, so it's as if we recursively call this routine 9 times successfully and die on the 10th recursion. The data structure I am trying to view is as follows: Club has many Seasons Season has many Schedules Schedule has many TimeSlots Club has many Locations Location has many Equipment Equipment has many Reservations Reservation has many Timeslots Through ReservationsTimeslots Club has many Members Member has many Reservations This is all loaded using 1 complex query (with multiple includes) into attr_accessor :data within my code. I also have a filter built around this which maps Schedules, Timeslots, and Calendar Days. So in Round numbers: Within my test database there are 8 clubs, 50 locations, 500 pieces of equipment, 30 seasons, 400 schedules, 3000 Members, 8000 Reservations and 31 Calendar Days. And the average number of attributes for each of these objects is 12. It's a rather large data map (1200 objects and a depth of 8) so it's possible we are hitting a limit.
I changed the variable to 1000 and then to 10000. Each time it added a bit (about 1/2 second) to the delay between when I click the expand button in the variable tree and the time the debugger disconnects, but what it did do is change the delay from immediate to 1 second and then to 10 seconds before the remainder of the log file is written out. So it looks like there are multiple problems. 1) The number of "seconds" for the timeout is behaving like a number of miliseconds. Like the jruby dev team missed a 1000 multiplier in the sleep() routine. 2) The log information that we need to look at comes earlier in the log file. I've attached the log file from one of my test runs. The debugger is detaching following the section: FINEST [org.rubyforge.debugcommons.Util]: Received: <frame no='38' file='/home/esmith/Apps/netbeans-dev-200911230200/ruby2/jruby-1.4.0/lib/ruby/1.8/webrick/httpserver.rb' line='65'> FINEST [org.rubyforge.debugcommons.Util]: Received: <frame no='39' file='/home/esmith/Apps/netbeans-dev-200911230200/ruby2/jruby-1.4.0/lib/ruby/1.8/webrick/server.rb' line='173'> FINEST [org.rubyforge.debugcommons.Util]: Received: </frames> WARNING [org.openide.text.CloneableEditorSupport]: org.netbeans.modules.csl.core.GsfDataObject$GenericEditorSupport should override asynchronousOpen(). See http://bits.netbeans.org/dev/javadoc/org-openide-text/apichanges.html#CloneableEditorSupport.asynchronousOpen Then it waits until the timeout expires to log the remainder: FINE [org.rubyforge.debugcommons.RubyDebuggerProxy]: Sending command debugger: frame 1; v l FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Processing: frame 1; v l</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Processing context: frame 1</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Selected frame no 0</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Processing context: v l</message> FINEST [org.rubyforge.debugcommons.Util]: Received: <variables> FINEST [org.rubyforge.debugcommons.Util]: Received: <variable name='self' kind='local' value='#<Resnet::Availability::Filter:0x73976>' type='Resnet::Availability::Filter' hasChildren='true' objectId='+0x3ee'> FINEST [org.rubyforge.debugcommons.Util]: Received: <variable name='c' kind='local' value='#<Club:0x4d8db0>' type='Club' hasChildren='true' objectId='+0x3f0'> FINEST [org.rubyforge.debugcommons.Util]: Received: <variable name='options' kind='local' value='Empty Hash' type='Hash' hasChildren='false' objectId='+0x3f2'> FINEST [org.rubyforge.debugcommons.Util]: Received: <variable name='user' kind='local' value='#<Goldberg::User:0xe7ef68>' type='Goldberg::User' hasChildren='true' objectId='+0x3f4'> FINEST [org.rubyforge.debugcommons.Util]: Received: </variables> FINE [org.rubyforge.debugcommons.RubyDebuggerProxy]: Sending command debugger: frame 1; v i +0x3ee FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Processing: frame 1; v i +0x3ee</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Processing context: frame 1</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Selected frame no 0</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Processing context: v i +0x3ee</message> FINEST [org.rubyforge.debugcommons.Util]: Received: <variables> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10000 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10000 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10000 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10000 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10000 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10000 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10000 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10000 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10000 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10000 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received message: <message debug='true'>Evaluating with timeout after 10000 sec</message> FINEST [org.rubyforge.debugcommons.Util]: Received: END_DOCUMENT event FINE [org.rubyforge.debugcommons.ReadersSupport]: ReadersSupport readloop [class org.rubyforge.debugcommons.ReadersSupport command loop] successfully finished. FINEST [org.rubyforge.debugcommons.RubyDebuggerProxy]: Socket reader loop finished.
Created attachment 91638 [details] IDE Log File with timeout of 10000
Thanks for looking into this. I haven't yet had a chance to investigate this much further, but in any case the fix needs to be done in the backend. I'm setting TM to 6.9, but of course can be fixed in 6.8 by the user by updating the debugger gems once this is fixed there.
It appears that we haven't been the only ones tracking this down. The folks at JetBrains have been hit with it too (http://jetbrains.net/devnet/message/5250520) I don't know if the debugger gem has been updated for the latest beta version [200911281400], but the mix of ruby-debug-ide 0.4.6 and ruby-debug-base 0.10.3.1-java appear to have (temporarily) fixed the problem. I'm going to run some additional tests with 200911281400 and if the capability remains in the next version, I'll mark this as closed.
I've filed this against ruby-debug-ide: http://rubyforge.org/tracker/index.php?func=detail&aid=28087&group_id=3085&atid=11903. Leaving this open as a task to track this.