Bug 579001

Note that after this bug occurres, whole WebYaST is somehow "flaky" - I cannot even display the control center.

Restart of webservice makes WebUI work again (without restart of webclient)

Looks like a more generic problem - I just ran into it with system time running from git locally.

OK, setting P2.

Are you able to reproduce it reliably? For me it seems to be very random...

I could reproduce it with 1.1.3 and 1.1.4. With 1.1.5 I get a different error. However, even after hitting it, I still can use the rest of WebYaST. When re-entering the dialog, I get the problem again.

  #<RuntimeError: attempted adding second root element to document>
/usr/lib/ruby/1.8/rexml/document.rb:92:in `<<'
/usr/lib/ruby/1.8/rexml/element.rb:868:in `add'
/usr/lib/ruby/1.8/rexml/child.rb:21:in `initialize'
/usr/lib/ruby/1.8/rexml/parent.rb:13:in `initialize'
/usr/lib/ruby/1.8/rexml/element.rb:59:in `initialize'
/usr/lib/ruby/1.8/rexml/element.rb:866:in `new'
/usr/lib/ruby/1.8/rexml/element.rb:866:in `add'
/usr/lib/ruby/1.8/rexml/element.rb:297:in `add_element'
/usr/lib/ruby/1.8/rexml/document.rb:99:in `add_element'
/usr/lib/ruby/1.8/rexml/parsers/treeparser.rb:33:in `parse'
/usr/lib/ruby/1.8/rexml/document.rb:227:in `build'
/usr/lib/ruby/1.8/rexml/document.rb:43:in `initialize'
/usr/lib/ruby/gems/1.8/gems/activesupport-2.3.5/lib/active_support/xml_mini/rexml.rb:17:in `new'
/usr/lib/ruby/gems/1.8/gems/activesupport-2.3.5/lib/active_support/xml_mini/rexml.rb:17:in `parse'
/usr/lib/ruby/gems/1.8/gems/activesupport-2.3.5/lib/active_support/xml_mini.rb:12:in `__send__'
/usr/lib/ruby/gems/1.8/gems/activesupport-2.3.5/lib/active_support/xml_mini.rb:12:in `parse'
/usr/lib/ruby/gems/1.8/gems/activesupport-2.3.5/lib/active_support/core_ext/hash/conversions.rb:164:in `from_xml'
/usr/lib/ruby/gems/1.8/gems/activeresource-2.3.5/lib/active_resource/formats/xml_format.rb:19:in `decode'
/usr/lib/ruby/gems/1.8/gems/activeresource-2.3.5/lib/active_resource/connection.rb:138:in `get'
/usr/lib/ruby/gems/1.8/gems/activeresource-2.3.5/lib/active_resource/base.rb:658:in `find_single'
/usr/lib/ruby/gems/1.8/gems/activeresource-2.3.5/lib/active_resource/base.rb:586:in `find'
/srv/www/yast/lib/proxy_loader.rb:56:in `load_proxy'
/srv/www/yast/vendor/plugins/software/app/controllers/repositories_controller.rb:25:in `show'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/base.rb:1331:in `send'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/base.rb:1331:in `perform_action_without_filters'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/filters.rb:617:in `call_filters'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/filters.rb:610:in `perform_action_without_benchmark'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/benchmarking.rb:68:in `perform_action_without_rescue'
/usr/lib/ruby/gems/1.8/gems/activesupport-2.3.5/lib/active_support/core_ext/benchmark.rb:17:in `ms'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/gems/1.8/gems/activesupport-2.3.5/lib/active_support/core_ext/benchmark.rb:17:in `ms'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/benchmarking.rb:68:in `perform_action_without_rescue'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/rescue.rb:160:in `perform_action_without_flash'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/flash.rb:146:in `perform_action'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/base.rb:532:in `send'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/base.rb:532:in `process_without_filters'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/filters.rb:606:in `process'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/base.rb:391:in `process'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/base.rb:386:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/routing/route_set.rb:437:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/dispatcher.rb:87:in `dispatch'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/dispatcher.rb:121:in `_call'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/dispatcher.rb:130:in `build_middleware_stack'
/srv/www/yast/lib/yast/rack/static_overlay.rb:47:in `call'
/srv/www/yast/lib/yast/rack/static_overlay.rb:47:in `call'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.5/lib/active_record/query_cache.rb:29:in `call'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/query_cache.rb:34:in `cache'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.5/lib/active_record/query_cache.rb:9:in `cache'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.5/lib/active_record/query_cache.rb:28:in `call'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:361:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/string_coercion.rb:25:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/head.rb:9:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/methodoverride.rb:24:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/params_parser.rb:15:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/session/cookie_store.rb:93:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/failsafe.rb:26:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/lock.rb:11:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/lock.rb:11:in `synchronize'
/usr/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/lock.rb:11:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/dispatcher.rb:106:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/content_length.rb:13:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/handler/fastcgi.rb:58:in `serve'
/usr/lib/ruby/gems/1.8/gems/rails-2.3.5/lib/fcgi_handler.rb:103:in `process_request'
/usr/lib/ruby/gems/1.8/gems/rails-2.3.5/lib/fcgi_handler.rb:153:in `with_signal_handler'
/usr/lib/ruby/gems/1.8/gems/rails-2.3.5/lib/fcgi_handler.rb:101:in `process_request'
/usr/lib/ruby/gems/1.8/gems/rails-2.3.5/lib/fcgi_handler.rb:78:in `process_each_request'
/usr/lib/ruby/gems/1.8/gems/rails-2.3.5/lib/fcgi_handler.rb:77:in `each'
/usr/lib/ruby/gems/1.8/gems/rails-2.3.5/lib/fcgi_handler.rb:77:in `process_each_request'
/usr/lib/ruby/gems/1.8/gems/rails-2.3.5/lib/fcgi_handler.rb:76:in `catch'
/usr/lib/ruby/gems/1.8/gems/rails-2.3.5/lib/fcgi_handler.rb:76:in `process_each_request'
/usr/lib/ruby/gems/1.8/gems/rails-2.3.5/lib/fcgi_handler.rb:51:in `process!'
/usr/lib/ruby/gems/1.8/gems/rails-2.3.5/lib/fcgi_handler.rb:23:in `process!'
/srv/www/yast/public/dispatch.fcgi:24
...
attempted adding second root element to document
Line: 
Position: 
Last 80 unconsumed characters:

To comment 4:
That's a different problem, see bnc#579039 (it just have been fixed).

I have finally moved forward:

The rest service has stdout redirected to /dev/null (/proc/3086/fd -> /dev/null), so the debugging trick from 
http://eigenclass.org/hiki.rb?ruby+live+process+introspection
cannot be used.

However, using the steps described at
http://weblog.jamisbuck.org/2006/9/22/inspecting-a-live-ruby-process
I was able to get:
0x87c6b98:	 "/usr/lib/ruby/vendor_ruby/1.8/dbus/bus.rb:716:in `select'"

When I reproduced the problem locally I could use the first debugging trick and the result is:

	from /usr/lib64/ruby/vendor_ruby/1.8/dbus/bus.rb:716:in `select'
	from /usr/lib64/ruby/vendor_ruby/1.8/dbus/bus.rb:716:in `run'
	from /local/lslezak/GIT/Yast/rest-service/webservice/../plugins/software/lib/packagekit.rb:142:in `transact'
	from /local/lslezak/GIT/Yast/rest-service/webservice/../plugins/software/app/models/repository.rb:30:in `find'
	from /local/lslezak/GIT/Yast/rest-service/webservice/../plugins/software/app/controllers/repositories_controller.rb:13:in `index'
	from /usr/lib64/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/base.rb:1331:in `send'
	from /usr/lib64/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/base.rb:1331:in `perform_action_without_filters'
	from /usr/lib64/ruby/gems/1.8/gems/actionpack-2.3.5/lib/action_controller/filters.rb:617:in `call_filters'
	from /usr/lib64/ruby/gems/1.8/gems/actionpack-2.3.5/lib
[and so on ..., the rest is not important]

So it seems to freeze somewhere in ruby-dbus code.

Unfortunately Martin is still on vacation.

Klaus, any idea what might went wrong?

Its apparently a (PackageKit?) timeout which is not properly handled.

  plugins/software/lib/packagekit.rb:142:in `transact'
starts a transaction (by sending a request do PackageKit via D-Bus)

  /usr/lib64/ruby/vendor_ruby/1.8/dbus/bus.rb:716:in `run'
'run' listens on the D-Bus for result messages
Each message has a "signal" name, identifying the type of message
run dispatches these signals based on the on_signal information that was set up before

 /usr/lib64/ruby/vendor_ruby/1.8/dbus/bus.rb:716:in `select'
thats a standard kernel select() call listening on network sockets.


The timeout can have two reasons

1. PackageKit does not send a reply
2. PackageKit does send a signal but there's no receiver set up

(There should be a "Finished" receiver set up, i.e.
      proxy.on_signal("Finished") {|u1,u2| dbusloop.quit }
 in rest-service/plugins/software/lib/packagekit.rb)

Hmm, the 'Finished' signal is captured via self.dbusloop

But the signal callback is not processed sometimes, I added some debugging messages (I'll attach a patch).

'dbus-monitor --system' output: 

signal sender=:1.124 -> dest=(null destination) serial=57 path=/766_beaadeed_data; interface=org.freedesktop.PackageKit.Transaction; member=RepoDetail
   string "http-download.opensuse.org-476132dc"
   string "openSUSE-11.2 Updates"
   boolean false
signal sender=:1.124 -> dest=(null destination) serial=58 path=/766_beaadeed_data; interface=org.freedesktop.PackageKit.Transaction; member=StatusChanged
   string "finished"
signal sender=:1.124 -> dest=(null destination) serial=59 path=/766_beaadeed_data; interface=org.freedesktop.PackageKit.Transaction; member=Finished
   string "success"
   uint32 38

The 'Finished' signal _was_ sent but it wasn't caught or the signal handler was not processed correctly.

Created attachment 342194 [details]
debugging patch

The patch prints:

Finishing RepoDetail signal handler
RepoDetail signal received: devel:tools:building, devel:tools:building, false
reading file...
                done
Finishing RepoDetail signal handler
RepoDetail signal received: http-download.opensuse.org-476132dc, openSUSE-11.2 Updates, false
reading file...
                done
Finishing RepoDetail signal handler

and then it stops.
The last repository signal was caught, (see the previous comment), but the following Finished signal got lost.

Um, it seems that ruby-dbus evaluates registered callbacks before dbusloop.run is entered. It calls Dbus introspection when installing signal handler and when it waits for the introspection result it receives and processes other siganl handlers.

--> #0 DBus::Connection.process(m#DBus::Message) 
       at line /usr/lib64/ruby/vendor_ruby/1.8/dbus/bus.rb:532
    #1 DBus::Connection.send_sync(m#DBus::Message) 
       at line /usr/lib64/ruby/vendor_ruby/1.8/dbus/bus.rb:492
    #2 AddMatch(arg0#String) at line (eval):22
    #3 DBus::Connection.add_match(mr#DBus::MatchRule) 
       at line /usr/lib64/ruby/vendor_ruby/1.8/dbus/bus.rb:512
    #4 DBus::ProxyObjectInterface.on_signal(bus#DBus::SystemBus, name#String) 
       at line /usr/lib64/ruby/vendor_ruby/1.8/dbus/introspect.rb:393
    #5 DBus::ProxyObject.[](name#String) 
       at line /usr/lib64/ruby/vendor_ruby/1.8/dbus/introspect.rb:458
    #6 PackageKit.dbusloop(proxy#DBus::ProxyObject) 
       at line /local/lslezak/GIT/Yast/rest-service/plugins/software/lib/packagekit.rb:33
    #7 PackageKit.transact(method#String, args#String, signal#String, bg_stat#NilClass,...) 
       at line /local/lslezak/GIT/Yast/rest-service/plugins/software/lib/packagekit.rb:148
    #8 Repository.find(what#Symbol) 
       at line /local/lslezak/GIT/Yast/rest-service/plugins/software/app/models/repository.rb:32

I have a single line patch which calls the introspection explicitly before registering signal handlers. But I don't know whether it is correct, 
the code is unbelievably complex (at least for me).

I'll attach the patch, please test it!

Created attachment 342206 [details]
Proposed patch

Ugh, the patch doesn't help, I created a simple loop which calls curl and it stopped after a while :-(

I'm giving up, the ruby-dbus code is really complex, reassigning to Martin...

I cannot reproduce this bug any more with Build 1.1.7.

Um, I guess the problem is still there, it's a race condition which might occur only rarely.

Could you run something like 

  curl -u root -c cookie.txt http://localhost:4984/login

and then 

  while true; do curl -b cookie.txt http://localhost:4984/repositories.xml > repositories.xml;done

inside the appliance?

For me it freezes after 20-30 attempts (in build 1.1.4).

I'll try the latest build.

*** Bug 579567 has been marked as a duplicate of this bug. ***

@#16: Yes, I can confirm that.

I'm looking at the code and I think I have a suspect in packagekit.rb.
I'm testing a new patch, let's see if it helps...

Yes, the problem was that the dbusloop object was created _after_ calling PackageKit via DBus. Depending on the actual timing the PackageKit result could be received _before_ entering the dbus loop which then hangs because no expected signal is received later.

After the fix it survived more than 40 minutes of intensive testing described in comment #16.

It was quite obvious in the code but I found it after adding a dozen of debug log messages...


Fixed in webyast-software-ws-0.1.8

Great, thanks !

I now opened bnc#580619 to (hopefully) detect such scenarios.

(In reply to comment #20)
> Yes, the problem was that the dbusloop object was created _after_ calling
> PackageKit via DBus.

For the record, actually no. If that were the case, there would still be a race condition, only with a shorter trigger window. What was too late (as a result of a previous refactoring) was the on_signal (org.freedesktop.DBus.AddMatch). But the fix ends up being right.