Post-mortem from today's board agenda train wreck

[Sam Ruby]

After years of behaving reasonably well, problems with the board agenda 
tool in January caused me to accelerate movement of this tool to a new 
vm (whimsy-vm2).  Which performed reasonably well in its new home in the 
weeks leading up to the board meeting, and then failed when it was 
heavily used.  On the bright side, investments made in logging appear to 
have paid off.  Bertrand captured the following:

https://paste.apache.org/7jMH
I've copied the relevant portions at the bottom of the note so that the 
stick around after the pastebin expires.

A lot is going on here.  For the first time we have "on tape" svn 
misbehaving.  We also seem to be dying in the LDAP failover logic.  And 
getting a mysterious "fiber called across threads" error when none of 
the relevant application code makes explicit use of fibers or threads.

Translation of terms for people coming from other programming languages:

  - phusion_passenger is essentially mod_ruby for Apache httpd.  It
    makes perfect sense that this function uses threads.

  - rack is essentially WSGI or servlet

  - fibers are green threads and as a relatively new addition to the
    language are unlikely to be used widely outside of the runtime
    library.

  - while not directly shown here, 'cycle' is essentially a
    generator.  I'll show why that's important next.

While I can't explain why svn and sqlite aren't getting along, nor why 
we appear to be in LDAP failover logic, I believe that I can solve the
fiber called across threads issue.  Here is the code from 
lib/whimsy/asf/ldap.rb:618:

    # Ensure we use each host in turn
    def self.next_host
       @he ||= hosts.cycle
       @he.next
    end

As cycle is both a generator and a builtin runtime library function, it 
makes sense that it is implemented using fibers internally.  And calling 
that from a web server that makes use of threads to dispatch requests 
who may be calling this function at the same time is a recipe for disaster.

And this code is new, as the LDAP failover logic was added in the past 
month.

My plans are to wrap the retry logic with a mutex as we don't need 
multiple threads trying to find an available LDAP server simultaneously. 
 And at the same time move away from the elegant cycle call to a more 
mundane but threadsafe Queue.

Fixing this still leaves a number of mysteries unsolved, but either they 
are related or can be isolated next month.

- Sam Ruby

"{
  "transcript": [
    "$ svn cleanup /srv/svn/foundation_board",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database",
    "svn: E200031: Additional errors:",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database",
    "$ svn update /srv/svn/foundation_board",
    "svn: E155004: Run 'svn cleanup' to remove locks (type 'svn help cleanup' for 
details)",
    "svn: E155004: Working copy '/srv/svn/foundation_board' locked",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database",
    "svn: E200031: Additional errors:",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database",
    "$ svn checkout --depth empty 
https://svn.apache.org/repos/private/foundation/board /tmp/d20160217-23947-1l3zjd3",
    " U   /tmp/d20160217-23947-1l3zjd3",
    "Checked out revision 65761.",
    "$ svn update /tmp/d20160217-23947-1l3zjd3/board_agenda_2016_02_17.txt",
    "Updating '/tmp/d20160217-23947-1l3zjd3/board_agenda_2016_02_17.txt':",
    "A    /tmp/d20160217-23947-1l3zjd3/board_agenda_2016_02_17.txt",
    "Updated to revision 65761.",
    "$ svn update /srv/svn/foundation_board/board_agenda_2016_02_17.txt",
    "svn: E155004: Run 'svn cleanup' to remove locks (type 'svn help cleanup' for 
details)",
    "svn: E155004: Working copy '/srv/svn/foundation_board' locked",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database",
    "svn: E200031: Additional errors:",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database"
  ],
  "exception": "#<FiberError: fiber called across threads>",
  "backtrace": [
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:618:in `next'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:618:in `next_host'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:77:in `block in connect'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:76:in `times'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:76:in `connect'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:111:in `init_ldap'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:135:in `search_one'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:269:in `list'",
    "/srv/whimsy/lib/whimsy/asf/agenda/front.rb:44:in `block (3 levels) in 
<class:Agenda>'",
    "/srv/whimsy/lib/whimsy/asf/agenda/front.rb:24:in `each'",
    "/srv/whimsy/lib/whimsy/asf/agenda/front.rb:24:in `block (2 levels) in 
<class:Agenda>'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:41:in `block in scan'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:39:in `each'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:39:in `scan'",
    "/srv/whimsy/lib/whimsy/asf/agenda/front.rb:14:in `block in 
<class:Agenda>'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:65:in `instance_exec'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:65:in `block in parse'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:65:in `each'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:65:in `parse'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:28:in `parse'",
    "/srv/whimsy/www/board/agenda/models/agenda.rb:18:in `update_cache'",
    "/srv/whimsy/www/board/agenda/models/agenda.rb:108:in `block in update'",
    "/srv/whimsy/www/board/agenda/models/agenda.rb:71:in `synchronize'",
    "/srv/whimsy/www/board/agenda/models/agenda.rb:71:in `update'",
    "/srv/whimsy/www/board/agenda/views/actions/refresh.json.rb:10:in 
`_evaluate'",
    "/srv/whimsy/www/board/agenda/routes.rb:104:in `block in <top (required)>'",
    "/srv/whimsy/lib/whimsy/asf/rack.rb:195:in `call'",
    "/srv/whimsy/lib/whimsy/asf/rack.rb:82:in `call'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97:in
 `process_request'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:160:in
 `accept_and_process_next_request'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:113:in
 `main_loop'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/request_handler.rb:416:in
 `block (3 levels) in start_threads'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/utils.rb:113:in
 `block in create_thread_and_abort_on_exception'"
  ]
}
" app.js:314:11
"{
  "transcript": [
    "$ svn cleanup /srv/svn/foundation_board",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database",
    "svn: E200031: Additional errors:",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database",
    "$ svn update /srv/svn/foundation_board",
    "svn: E155004: Run 'svn cleanup' to remove locks (type 'svn help cleanup' for 
details)",
    "svn: E155004: Working copy '/srv/svn/foundation_board' locked",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database",
    "svn: E200031: Additional errors:",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database",
    "$ svn checkout --depth empty 
https://svn.apache.org/repos/private/foundation/board /tmp/d20160217-23947-14885nw",
    " U   /tmp/d20160217-23947-14885nw",
    "Checked out revision 65761.",
    "$ svn update /tmp/d20160217-23947-14885nw/board_agenda_2016_02_17.txt",
    "Updating '/tmp/d20160217-23947-14885nw/board_agenda_2016_02_17.txt':",
    "A    /tmp/d20160217-23947-14885nw/board_agenda_2016_02_17.txt",
    "Updated to revision 65761.",
    "$ svn update /srv/svn/foundation_board/board_agenda_2016_02_17.txt",
    "svn: E155004: Run 'svn cleanup' to remove locks (type 'svn help cleanup' for 
details)",
    "svn: E155004: Working copy '/srv/svn/foundation_board' locked",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database",
    "svn: E200031: Additional errors:",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database"
  ],
  "exception": "#<FiberError: fiber called across threads>",
  "backtrace": [
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:618:in `next'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:618:in `next_host'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:77:in `block in connect'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:76:in `times'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:76:in `connect'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:111:in `init_ldap'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:135:in `search_one'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:269:in `list'",
    "/srv/whimsy/lib/whimsy/asf/agenda/front.rb:44:in `block (3 levels) in 
<class:Agenda>'",
    "/srv/whimsy/lib/whimsy/asf/agenda/front.rb:24:in `each'",
    "/srv/whimsy/lib/whimsy/asf/agenda/front.rb:24:in `block (2 levels) in 
<class:Agenda>'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:41:in `block in scan'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:39:in `each'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:39:in `scan'",
    "/srv/whimsy/lib/whimsy/asf/agenda/front.rb:14:in `block in 
<class:Agenda>'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:65:in `instance_exec'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:65:in `block in parse'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:65:in `each'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:65:in `parse'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:28:in `parse'",
    "/srv/whimsy/www/board/agenda/models/agenda.rb:18:in `update_cache'",
    "/srv/whimsy/www/board/agenda/models/agenda.rb:108:in `block in update'",
    "/srv/whimsy/www/board/agenda/models/agenda.rb:71:in `synchronize'",
    "/srv/whimsy/www/board/agenda/models/agenda.rb:71:in `update'",
    "/srv/whimsy/www/board/agenda/views/actions/refresh.json.rb:10:in 
`_evaluate'",
    "/srv/whimsy/www/board/agenda/routes.rb:104:in `block in <top (required)>'",
    "/srv/whimsy/lib/whimsy/asf/rack.rb:195:in `call'",
    "/srv/whimsy/lib/whimsy/asf/rack.rb:82:in `call'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97:in
 `process_request'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:160:in
 `accept_and_process_next_request'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:113:in
 `main_loop'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/request_handler.rb:416:in
 `block (3 levels) in start_threads'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/utils.rb:113:in
 `block in create_thread_and_abort_on_exception'"
  ]
}
" app.js:314:11
"{
  "transcript": [
    "$ svn checkout --depth empty 
https://svn.apache.org/repos/private/foundation/board /tmp/d20160217-23947-dqngg4",
    " U   /tmp/d20160217-23947-dqngg4",
    "Checked out revision 65761.",
    "$ svn update /tmp/d20160217-23947-dqngg4/board_agenda_2016_02_17.txt",
    "Updating '/tmp/d20160217-23947-dqngg4/board_agenda_2016_02_17.txt':",
    "A    /tmp/d20160217-23947-dqngg4/board_agenda_2016_02_17.txt",
    "Updated to revision 65761.",
    "$ svn commit /tmp/d20160217-23947-dqngg4/board_agenda_2016_02_17.txt -m 
Approve\\ W3C\\ Relations,\\ Legal\\ Affairs,\\ Security\\ Team'\n'Comment\\ on\\ 
President",
    "Sending        tmp/d20160217-23947-dqngg4/board_agenda_2016_02_17.txt",
    "Transmitting file data .",
    "Committed revision 65762.",
    "$ svn update /srv/svn/foundation_board/board_agenda_2016_02_17.txt",
    "svn: E155004: Run 'svn cleanup' to remove locks (type 'svn help cleanup' for 
details)",
    "svn: E155004: Working copy '/srv/svn/foundation_board' locked",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database",
    "svn: E200031: Additional errors:",
    "svn: E200031: sqlite[S8]: attempt to write a readonly database"
  ],
  "exception": "#<FiberError: fiber called across threads>",
  "backtrace": [
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:618:in `next'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:618:in `next_host'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:77:in `block in connect'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:76:in `times'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:76:in `connect'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:111:in `init_ldap'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:135:in `search_one'",
    "/srv/whimsy/lib/whimsy/asf/ldap.rb:269:in `list'",
    "/srv/whimsy/lib/whimsy/asf/agenda/front.rb:44:in `block (3 levels) in 
<class:Agenda>'",
    "/srv/whimsy/lib/whimsy/asf/agenda/front.rb:24:in `each'",
    "/srv/whimsy/lib/whimsy/asf/agenda/front.rb:24:in `block (2 levels) in 
<class:Agenda>'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:41:in `block in scan'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:39:in `each'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:39:in `scan'",
    "/srv/whimsy/lib/whimsy/asf/agenda/front.rb:14:in `block in 
<class:Agenda>'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:65:in `instance_exec'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:65:in `block in parse'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:65:in `each'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:65:in `parse'",
    "/srv/whimsy/lib/whimsy/asf/agenda.rb:28:in `parse'",
    "/srv/whimsy/www/board/agenda/models/agenda.rb:18:in `update_cache'",
    "/srv/whimsy/www/board/agenda/models/agenda.rb:108:in `block in update'",
    "/srv/whimsy/www/board/agenda/models/agenda.rb:71:in `synchronize'",
    "/srv/whimsy/www/board/agenda/models/agenda.rb:71:in `update'",
    "/srv/whimsy/www/board/agenda/views/actions/commit.json.rb:11:in 
`_evaluate'",
    "/srv/whimsy/www/board/agenda/routes.rb:104:in `block in <top (required)>'",
    "/srv/whimsy/lib/whimsy/asf/rack.rb:195:in `call'",
    "/srv/whimsy/lib/whimsy/asf/rack.rb:82:in `call'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97:in
 `process_request'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:160:in
 `accept_and_process_next_request'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:113:in
 `main_loop'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/request_handler.rb:416:in
 `block (3 levels) in start_threads'",
    
"/usr/local/rvm/gems/ruby-2.3.0/gems/passenger-5.0.23/src/ruby_supportlib/phusion_passenger/utils.rb:113:in
 `block in create_thread_and_abort_on_exception'"
  ]
}