Discobot not responding to bookmark?

After upgrading one of my Discourse instances and loading an old backup I can no longer get past the initial discobot message for new users where it wants you to bookmark the message. Telling it to skip the step gives no response either.

It responds just fine to other text commands, so I’m curious what mechanism is used by the bot to look for the bookmark status changing and where I should start troubleshooting.

I can see the bookmark being set in production.log but the bot doesn’t want to pick up on it for some reason

Started PUT "/posts/386/bookmark" for 127.0.0.1 at 2018-05-30 18:00:36 +0000
Processing by PostsController#bookmark as */*
  Parameters: {"bookmarked"=>"true", "post_id"=>"386"}
Completed 200 OK in 72ms (Views: 0.2ms | ActiveRecord: 36.0ms)

The weirdest thing is that the entire advanced user tutorial works just fine, and it looks for deleted posts, edited posts, changed notification status and so on which probably work the same way under the hood…?

That’s odd, any ideas @tgxworld?

@ssvenn Can you check if Sidekiq is running for your instance? Any errors in /logs?

1 Like

Sidekiq is running, i do get these errors which sound related though:
image

Here’s the backtrace for that error

backtrace
/var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mini_racer-0.1.15/lib/mini_racer.rb:182:in `eval_unsafe' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mini_racer-0.1.15/lib/mini_racer.rb:182:in `block (2 levels) in eval' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mini_racer-0.1.15/lib/mini_racer.rb:262:in `timeout' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mini_racer-0.1.15/lib/mini_racer.rb:181:in `block in eval' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mini_racer-0.1.15/lib/mini_racer.rb:69:in `block in with_lock' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mini_racer-0.1.15/lib/mini_racer.rb:69:in `synchronize' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mini_racer-0.1.15/lib/mini_racer.rb:69:in `with_lock' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/mini_racer-0.1.15/lib/mini_racer.rb:179:in `eval' /var/www/discourse/lib/pretty_text.rb:187:in `block in markdown' /var/www/discourse/lib/pretty_text.rb:405:in `block in protect' /var/www/discourse/lib/pretty_text.rb:404:in `synchronize' /var/www/discourse/lib/pretty_text.rb:404:in `protect' /var/www/discourse/lib/pretty_text.rb:142:in `markdown' /var/www/discourse/lib/pretty_text.rb:252:in `cook' /var/www/discourse/app/models/post_analyzer.rb:31:in `cook' /var/www/discourse/app/models/post_analyzer.rb:132:in `cooked_stripped' /var/www/discourse/app/models/post_analyzer.rb:114:in `raw_links' /var/www/discourse/app/models/post_analyzer.rb:125:in `link_count' /var/www/discourse/app/models/post.rb:233:in `block (2 levels) in <class:Post>' /var/www/discourse/lib/validators/post_validator.rb:112:in `can_post_links_validator' /var/www/discourse/lib/validators/post_validator.rb:18:in `validate' /var/www/discourse/lib/post_creator.rb:154:in `valid?' /var/www/discourse/lib/post_creator.rb:162:in `create' /var/www/discourse/lib/post_creator.rb:205:in `create!' /var/www/discourse/lib/post_creator.rb:241:in `create!' /var/www/discourse/plugins/discourse-narrative-bot/lib/discourse_narrative_bot/actions.rb:22:in `reply_to' /var/www/discourse/plugins/discourse-narrative-bot/lib/discourse_narrative_bot/new_user_narrative.rb:236:in `reply_to_bookmark' /var/www/discourse/plugins/discourse-narrative-bot/lib/discourse_narrative_bot/base.rb:51:in `block in input' /var/www/discourse/plugins/discourse-narrative-bot/lib/discourse_narrative_bot/new_user_narrative.rb:138:in `block in synchronize' /var/www/discourse/lib/distributed_mutex.rb:21:in `synchronize' /var/www/discourse/lib/distributed_mutex.rb:5:in `synchronize' /var/www/discourse/plugins/discourse-narrative-bot/lib/discourse_narrative_bot/new_user_narrative.rb:138:in `synchronize' /var/www/discourse/plugins/discourse-narrative-bot/lib/discourse_narrative_bot/base.rb:13:in `input' /var/www/discourse/plugins/discourse-narrative-bot/lib/discourse_narrative_bot/track_selector.rb:59:in `select' /var/www/discourse/plugins/discourse-narrative-bot/autoload/jobs/bot_input.rb:13:in `block in execute' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/i18n-0.8.6/lib/i18n.rb:257:in `with_locale' /var/www/discourse/plugins/discourse-narrative-bot/autoload/jobs/bot_input.rb:9:in `execute' /var/www/discourse/app/jobs/base.rb:134:in `block (2 levels) in perform' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/rails_multisite-2.0.4/lib/rails_multisite/connection_management.rb:63:in `with_connection' /var/www/discourse/app/jobs/base.rb:129:in `block in perform' /var/www/discourse/app/jobs/base.rb:125:in `each' /var/www/discourse/app/jobs/base.rb:125:in `perform' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:187:in `execute_job' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:169:in `block (2 levels) in process' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:128:in `block in invoke' /var/www/discourse/lib/sidekiq/pausable.rb:80:in `call' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:130:in `block in invoke' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:133:in `invoke' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:168:in `block in process' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:139:in `block (6 levels) in dispatch' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/job_retry.rb:98:in `local' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:138:in `block (5 levels) in dispatch' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq.rb:36:in `block in <module:Sidekiq>' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:134:in `block (4 levels) in dispatch' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:199:in `stats' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:129:in `block (3 levels) in dispatch' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/job_logger.rb:8:in `call' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:128:in `block (2 levels) in dispatch' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/job_retry.rb:73:in `global' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:127:in `block in dispatch' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/logging.rb:48:in `with_context' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/logging.rb:42:in `with_job_hash_context' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:126:in `dispatch' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:167:in `process' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:85:in `process_one' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:73:in `run' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/util.rb:16:in `watchdog' /var/www/discourse/vendor/bundle/ruby/2.4.0/gems/sidekiq-5.1.3/lib/sidekiq/util.rb:25:in `block in safe_thread'

the ‘env’ tab contains this:

hostname     webdis-app
process_id     171
application_version     864ada835b2d1d0483950e02a9ef62c14f8e0519
current_db     default
current_hostname     forum
job     Jobs::BotInput
problem_db     default
               opts
               user_id       [1, 5, 36]
               post_id       [351, 360, 362, 364, 368, 371, 375, 386, 390, 410, 414, 431, 46, 433]
               input         bookmark
               current_site_id default

This seems to be a queue of bookmarked tutorial posts building up, I asked another user to try the tutorial and their post has been added to the end of the queue

I’ve tried restoring the same database dump to a different instance, it seems to be working fine there. The broken one is running on an isolated intranet, I must have messed up something during the installation.

I will try redoing the installation from scratch and restoring again, but it would be nice to know more about the internal workings of the bot and how I could further troubleshoot the job that is causing issues :slight_smile:

2 Likes

Well then, that sure was a weird root cause!
After spending some time with tcpdump I noticed my Discourse host reaching out to text-lb.esams.wikimedia.org on port 443 right after I click the bookmark icon. Our firewall drops traffic it doesn’t like instead of rejecting it, and that often causes sessions to hang for a while.

The problem was that I had “enable inline onebox on all domains” turned on and since the next message in the script from discobot contains three wikipedia links it got hung up on something in the onebox handler for too long. As soon as I disabled that setting everything works fine and discobot responds right away :triumph:

Sorry about the unsupported edge case, this installation is using the How to install Discourse on an isolated CentOS 7 server method which makes my life harder than it has to be (at least until I can convince the security guys at work that Discourse isn’t scary and just let it have internet access)

5 Likes