Lita 4.2.0 and current lita-hipchat bot won't connect without debug true

[Generic42]

I'm running into an issue with the 'debug' mode if it is undefined or set to 'false' then the client won't connect.

[jimmycuadra]

Can you provide a Gemfile and configuration file that reproduces this?

[Generic42]

source "https://rubygems.org"

gem "lita"

# Uncomment to use the HipChat adapter
gem "lita-hipchat"

# Uncomment to use the IRC adapter
# gem "lita-irc"

# Add handlers to give Lita new functionality.
# For example:
 gem "lita-google-images"
# gem "lita-karma"
gem "lita-dice"
#gem "lita-dyn"

# A Lita handler that enhances text by replacing opaque machine identifiers with that machine's hostname
gem "lita-enhance"

gem "lita-pugbomb" 

Lita.configure do |config|
  # The name your robot will use.
  config.robot.name = "Lita Bot"

  # The locale code for the language to use.
  # config.robot.locale = :en

  # The severity of messages to log. Options are:
  # :debug, :info, :warn, :error, :fatal
  # Messages at the selected level and above will be logged.
  config.robot.log_level = :info

  # An array of user IDs that are considered administrators. These users
  # the ability to add and remove other users from authorization groups.
  # What is considered a user ID will change depending on which adapter you use.
  config.robot.admins = ["hipchat ids"]

  # The adapter you want to connect with. Make sure you've added the
  # appropriate gem to the Gemfile.
  config.robot.adapter = :hipchat
  config.adapters.hipchat.debug = true 
  config.adapters.hipchat.jid = "username"
  config.adapters.hipchat.password = "password"
  config.adapters.hipchat.rooms = :all

  ## Example: Set options for the chosen adapter.
  # config.adapter.username = "myname"
  # config.adapter.password = "secret"

  ## Example: Set options for the Redis connection.
  config.redis.host = "127.0.0.1"
  config.redis.port = 6379

  ## Example: Set configuration for any loaded handlers. See the handler's
  ## documentation for options.
  # config.handlers.some_handler.some_config_key = "value"

  # lita-dyn Handlers
  #config.handlers.dyn.customer
  #config.handlers.dyn.username
  #config.handlers.dyn.password


end

[jimmycuadra]

Lita works as expected for me with the above details, though of course I had to change the username and password for my own account. Does it work without turning debug on if you specify rooms explicitly instead of using :all?

[Generic42]

I tried joining one specific room with it on and then again with it off and had no luck with it off.

[jlambert121]

I just ran into this, worked fine on Friday on my test box, today I had to enable debug mode for the connection to work. Here's the installed gems too if that helps:

Gems included by the bundle:

• activesupport (4.2.1)
• bundler (1.7.4)
• faraday (0.9.1)
• http_router (0.11.1)
• i18n (0.7.0)
• ice_nine (0.11.1)
• jira-ruby (0.1.13)
• json (1.8.2)
• lita (4.3.1)
• lita-chuck_norris (0.0.1)
• lita-corporate-bs-generator (1.0.0)
• lita-cowsay (0.1.1)
• lita-excuses (0.0.6)
• lita-hipchat (2.1.1)
• lita-jira (0.5.0)
• lita-jira-issues (0.2.1)
• lita-likeaboss (1.1.0)
• lita-poop (1.0.2)
• lita-xkcd (0.0.5)
• mini_portile (0.6.2)
• minitest (5.5.1)
• multi_json (1.11.0)
• multipart-post (2.0.0)
• nokogiri (1.6.6.2)
• oauth (0.4.7)
• puma (2.11.1)
• rack (1.6.0)
• rb-readline (0.5.2)
• redis (3.2.1)
• redis-namespace (1.5.1)
• ruby_cowsay (0.1.1)
• thor (0.19.1)
• thread_safe (0.3.5)
• tzinfo (1.2.2)
• url_mount (0.2.1)
• xmpp4r (0.5.6)

[arohter]

Yes, I am running into this same problem. (Running with config.adapters.hipchat.rooms = :all) It's not failing 100% of the time, but definitely fails to connect regularly (unless debug is set to true).

Last log line is: `[2015-05-05 08:50:05 UTC] INFO: Connecting to HipChat.`` and fails to make it to the 'Joining room' log line.

Looks like some sort of timing issue....

[jimmycuadra]

I'd love to just blame it on the xmpp4r gem (and that probably will end up being where the bug is) but I haven't been able to reproduce this yet. :(

[arohter]

Had another play without debug; attempt finally times out with:

[2015-06-17 07:03:29 UTC] INFO: Connecting to HipChat.
/mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/xmpp4r-0.5.6/lib/xmpp4r/connection.rb:92:in `initialize': can't create Thread: Resource temporarily unavailable (ThreadError)
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/xmpp4r-0.5.6/lib/xmpp4r/connection.rb:92:in `new'
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/xmpp4r-0.5.6/lib/xmpp4r/connection.rb:92:in `connect'
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/xmpp4r-0.5.6/lib/xmpp4r/client.rb:71:in `connect'
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/lita-hipchat-2.1.3/lib/lita/adapters/hipchat/connector.rb:113:in `client_connect'
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/lita-hipchat-2.1.3/lib/lita/adapters/hipchat/connector.rb:32:in `connect'
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/lita-hipchat-2.1.3/lib/lita/adapters/hipchat.rb:42:in `run'
    from /mnt/deployed/lita/releases/lita_20150617-065941_223_aafcf53b14_checklist/cache/bundle/ruby/2.1.0/gems/lita-4.4.3/lib/lita/robot.rb:77:in `run'
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/lita-4.4.3/lib/lita.rb:80:in `run'
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/lita-4.4.3/lib/lita/cli.rb:77:in `start'
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/thor-0.19.1/lib/thor/command.rb:27:in `run'
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/thor-0.19.1/lib/thor/invocation.rb:126:in `invoke_command'
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/thor-0.19.1/lib/thor.rb:359:in `dispatch'
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/thor-0.19.1/lib/thor/base.rb:440:in `start'
    from /mnt/deployed/lita/current/cache/bundle/ruby/2.1.0/gems/lita-4.4.3/bin/lita:6:in `<top (required)>'
    from /mnt/deployed/lita/current/bin/lita:16:in `load'
    from /mnt/deployed/lita/current/bin/lita:16:in `<main>'

[arohter]

OK, I think I've worked around the race condition.

When :all rooms is enabled, the hipchat adapter calls https://github.com/jimmycuadra/lita-hipchat/blob/master/lib/lita/adapters/hipchat/connector.rb#L60 to get a list of the available rooms. This is issued immediately after the initial adapter connect() op, which I believe hits https://github.com/xmpp4r/xmpp4r/blob/master/lib/xmpp4r/observable/helper.rb#L200 , which isn't fully thread safe...

Conveniently, lita happens to fire an event in-between the connect and room-list calls, so this simple hack seems to fix things for me:

on(:connected) do |payload|
  puts "Waiting for connection to settle ..."
  sleep 3
end

[jimmycuadra]

Interesting! Thank you for debugging! I suppose this means that debug mode being turned on fixing it is just because it adds just enough delay to prevent the race condition.

[arohter]

Ya exactly. Wouldn't be the first time I've seen turning on logging magically "fix" race conditions :smile: My sleep 3 is probably 2.999999 seconds more than needed, but better safe than sorry.

[jimmycuadra]

Hey, everyone! I added some synchronization code that may address this issue. Please try the new lita-hipchat 3.0 and see if you're still getting this crash. Thank you and apologies for how long this issue has been open!

[Darep]

Thanks Jimmy, appreciate the effort! Unfortunately, it's still getting stuck in "Connecting to HipChat" at least for us, hehe :D

Edit: As a sidenote, when running our bot on any development machine, it connects fine even with debug: false. But when I run it on our beefy production server, it only connects with debug: true.

[jimmycuadra]

Frustrating! There must be a race condition elsewhere. Or perhaps the way I implemented the synchronization didn't actually work...

[Generic42]

Just updated to 4.2.0 and I'm still running into the same condition with debug being required. If I can provide more information, please let me know.