Introspection fails when called multiple times in threads

[zaburt]

I am trying to build a Rails application that regularly checks network status, Systemd service status etc. showing them on the UI. I need to use Puma which works with threads. When the application makes calls to DBus we start getting DBus::InvalidPacketException over and over during introspection. I am not sure if it is because of using threads, or if threads just makes it easier to reproduce (ex. calling DBus too fast).

I see it happen on OpenSUSE 42.3 and Ubuntu 16.04. Happens with Ruby 2.4.3 and 2.3.6, did not try other Ruby versions. This is reproducable with 2 threads too. Systemd is just an example, issue happens when calling NetworkManager too.

require 'dbus'

PARALLEL = 5
UNIT_NAME = 'ruby_dbus_test.service'

def local_service_unit_is_active(k)
  puts "current thread #{Thread.current[:num]}\n"
  sys_bus = DBus.system_bus
  core_service = sys_bus.service('org.freedesktop.systemd1')
  obj = core_service.object('/org/freedesktop/systemd1')
  obj.default_iface = 'org.freedesktop.systemd1'

  puts "before obj.introspect #{Thread.current[:num]}\n"
  obj.introspect
  puts "after obj.introspect #{Thread.current[:num]}\n"
  obj
end

def build_thread(k)
  Thread.new do
    Thread.current.abort_on_exception = true
    Thread.current[:num] = k

    resp = local_service_unit_is_active(UNIT_NAME)
    puts "\nFINISHED: result for #{k} active: #{resp.bus.inspect}\n"
  end
end

threads = []

PARALLEL.times do |k|
  puts "building thread #{k + 1} out of #{PARALLEL}"
  threads << build_thread(k)
end

threads.each(&:join)

and the errors I get changes time to time but they all look like introspection data is not correct so it is not parsed properly

/home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/marshall.rb:183:in `do_parse': DBus::InvalidPacketException (DBus::InvalidPacketException)
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/marshall.rb:62:in `block in unmarshall'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/marshall.rb:61:in `each'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/marshall.rb:61:in `unmarshall'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/message.rb:201:in `unmarshall_buffer'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/message_queue.rb:139:in `message_from_buffer_nonblock'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/message_queue.rb:38:in `pop'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/bus.rb:441:in `wait_for_message'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/bus.rb:458:in `send_sync'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/bus.rb:339:in `send_sync_or_async'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/bus.rb:365:in `introspect_data'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/proxy_object.rb:73:in `introspect'
        from ./multiple_dbus_calls.rb:18:in `local_service_unit_is_active'
        from ./multiple_dbus_calls.rb:28:in `block in build_thread'

/home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/marshall.rb:103:in `read_string': String is not nul-terminated (DBus::InvalidPacketException)
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/marshall.rb:212:in `do_parse'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/marshall.rb:62:in `block in unmarshall'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/marshall.rb:61:in `each'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/marshall.rb:61:in `unmarshall'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/message.rb:227:in `unmarshall_buffer'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/message_queue.rb:139:in `message_from_buffer_nonblock'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/message_queue.rb:38:in `pop'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/bus.rb:441:in `wait_for_message'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/bus.rb:453:in `send_sync'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/bus.rb:339:in `send_sync_or_async'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/bus.rb:365:in `introspect_data'
        from /home/zaburt/.rvm/gems/ruby-2.4.3@dbus_test/gems/ruby-dbus-0.14.1/lib/dbus/proxy_object.rb:73:in `introspect'
        from ./multiple_dbus_calls.rb:18:in `local_service_unit_is_active'
        from ./multiple_dbus_calls.rb:28:in `block in build_thread'

You can find the sample script to reproduce the issue (no Rails, just Ruby) and some info here too https://github.com/zaburt/ruby-dbus-test . I can try out any test code or suggestions.

[mvidner]

Hi, thanks for the report!

In ruby-dbus, thread safety is more of an accident than a goal. That said, I think I have found a workaround for your use case:

-   sys_bus = DBus.system_bus
+   sys_bus = DBus::ASystemBus.new

which makes each thread use its own connection. With that, your example works for me. Does it help for you?

I should document that.

[zaburt]

Thank you @mvidner that works very well ! I even tried the sample script with 200 threads running in parallel and did not see any issues. Will do more tests with Puma. Documenting this would be great as other people may hit this too.

I don't know if we should close this issue or wait for documentation update, or if you have something else in mind.

[mvidner]

Good to hear that! I'll document it and then close this myself.