Multiple downloads of a driver at the same time causes exceptions

[brenogazzola]

Summary

I'm using selenium on production to generate screenshots from websites. Every time I deploy a new release on Heroku, the worker dynos are shutdown and new ones are brought online. Each dyno has 10 sidekiq processes running.

Since there is no driver cached when the dynos come online, all 10 sidekiq processes attempt to download it. This causes three different errors, depending on the timing of each job:

ChildProcess::LaunchError - Text file busy - /app/.webdrivers/chromedriver

RuntimeError - Could not decompress chromedriver_linux64.zip to get /app/.webdrivers/chromedriver

Errno::ENOENT - No such file or directory @ apply2files - /app/.webdrivers/chromedriver

Debug Info

Please provide the following information for bug reports:

• Webdrivers version: 4.1.1
• Ruby version: 2.6.4
• Operating system / CI Environment: Heroku-18
• Browser and version: Chrome Stable

Expected Behavior

No exceptions should happen.

Actual Behavior

Three different exceptions are thrown, depending on the exact timing when each process attempts to download/decompress/read the driver file.

Text file busy

ChildProcess::LaunchError: Text file busy - /app/.webdrivers/chromedriver
  from childprocess/unix/fork_exec_process.rb:58:in `launch_process'
  from childprocess/abstract_process.rb:81:in `start'
  from selenium/webdriver/common/service.rb:172:in `start_process'
  from selenium/webdriver/common/service.rb:110:in `block in start'
  from selenium/webdriver/common/socket_lock.rb:41:in `locked'
  from selenium/webdriver/common/service.rb:108:in `start'
  from selenium/webdriver/common/driver.rb:303:in `service_url'
  from selenium/webdriver/chrome/driver.rb:40:in `initialize'
  from selenium/webdriver/common/driver.rb:46:in `new'
  from selenium/webdriver/common/driver.rb:46:in `for'
  from selenium/webdriver.rb:88:in `for'
  from app/jobs/generate_invitation_image_job.rb:35:in `take_screenshot'
  from app/jobs/generate_invitation_image_job.rb:18:in `perform'
  from active_job/execution.rb:39:in `block in perform_now'
  from active_support/callbacks.rb:112:in `block in run_callbacks'
  from raven/integrations/rails/active_job.rb:18:in `capture_and_reraise_with_sentry'
  from raven/integrations/rails/active_job.rb:12:in `block (2 levels) in included'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from i18n.rb:297:in `with_locale'
  from active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from active_support/core_ext/time/zones.rb:66:in `use_zone'
  from active_job/timezones.rb:9:in `block (2 levels) in <module:Timezones>'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from active_job/logging.rb:25:in `block (4 levels) in <module:Logging>'
  from active_support/notifications.rb:180:in `block in instrument'
  from active_support/notifications/instrumenter.rb:24:in `instrument'
  from active_support/notifications.rb:180:in `instrument'
  from active_job/logging.rb:24:in `block (3 levels) in <module:Logging>'
  from active_job/logging.rb:45:in `block in tag_logger'
  from active_support/tagged_logging.rb:80:in `block in tagged'
  from active_support/tagged_logging.rb:28:in `tagged'
  from active_support/tagged_logging.rb:80:in `tagged'
  from active_job/logging.rb:45:in `tag_logger'
  from active_job/logging.rb:21:in `block (2 levels) in <module:Logging>'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from active_support/callbacks.rb:139:in `run_callbacks'
  from active_job/execution.rb:38:in `perform_now'
  from active_job/execution.rb:24:in `block in execute'
  from active_support/callbacks.rb:112:in `block in run_callbacks'
  from active_job/railtie.rb:43:in `block (4 levels) in <class:Railtie>'
  from active_support/execution_wrapper.rb:88:in `wrap'
  from active_support/reloader.rb:72:in `block in wrap'
  from active_support/execution_wrapper.rb:84:in `wrap'
  from active_support/reloader.rb:71:in `wrap'
  from active_job/railtie.rb:42:in `block (3 levels) in <class:Railtie>'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from active_support/callbacks.rb:139:in `run_callbacks'
  from active_job/execution.rb:22:in `execute'
  from active_job/queue_adapters/sidekiq_adapter.rb:42:in `perform'
  from sidekiq/processor.rb:192:in `execute_job'
  from sidekiq/processor.rb:165:in `block (2 levels) in process'
  from sidekiq/middleware/chain.rb:128:in `block in invoke'
  from raven/integrations/sidekiq.rb:9:in `call'
  from sidekiq/middleware/chain.rb:130:in `block in invoke'
  from sidekiq/middleware/chain.rb:133:in `invoke'
  from sidekiq/processor.rb:164:in `block in process'
  from sidekiq/processor.rb:137:in `block (6 levels) in dispatch'
  from sidekiq/job_retry.rb:109:in `local'
  from sidekiq/processor.rb:136:in `block (5 levels) in dispatch'
  from sidekiq/rails.rb:43:in `block in call'
  from active_support/execution_wrapper.rb:88:in `wrap'
  from active_support/reloader.rb:72:in `block in wrap'
  from active_support/execution_wrapper.rb:88:in `wrap'
  from active_support/reloader.rb:71:in `wrap'
  from sidekiq/rails.rb:42:in `call'
  from sidekiq/processor.rb:132:in `block (4 levels) in dispatch'
  from sidekiq/processor.rb:250:in `stats'
  from sidekiq/processor.rb:127:in `block (3 levels) in dispatch'
  from sidekiq/job_logger.rb:8:in `call'
  from sidekiq/processor.rb:126:in `block (2 levels) in dispatch'
  from sidekiq/job_retry.rb:74:in `global'
  from sidekiq/processor.rb:125:in `block in dispatch'
  from sidekiq/logging.rb:48:in `with_context'
  from sidekiq/logging.rb:42:in `with_job_hash_context'
  from sidekiq/processor.rb:124:in `dispatch'
  from sidekiq/processor.rb:163:in `process'
  from sidekiq/processor.rb:83:in `process_one'
  from sidekiq/processor.rb:71:in `run'
  from sidekiq/util.rb:16:in `watchdog'
  from sidekiq/util.rb:25:in `block in safe_thread'

RuntimeError

RuntimeError: Could not decompress chromedriver_linux64.zip to get /app/.webdrivers/chromedriver
  from webdrivers/system.rb:98:in `decompress_file'
  from webdrivers/system.rb:74:in `block in download_file'
  from webdrivers/system.rb:64:in `chdir'
  from webdrivers/system.rb:64:in `download_file'
  from webdrivers/system.rb:55:in `download'
  from webdrivers/common.rb:99:in `update'
  from webdrivers/chromedriver.rb:119:in `block in <main>'
  from selenium/webdriver/common/service.rb:133:in `binary_path'
  from selenium/webdriver/common/service.rb:94:in `initialize'
  from selenium/webdriver/common/service.rb:41:in `new'
  from selenium/webdriver/common/service.rb:41:in `chrome'
  from selenium/webdriver/common/driver.rb:299:in `service_url'
  from selenium/webdriver/chrome/driver.rb:40:in `initialize'
  from selenium/webdriver/common/driver.rb:46:in `new'
  from selenium/webdriver/common/driver.rb:46:in `for'
  from selenium/webdriver.rb:88:in `for'
  from app/jobs/generate_website_image_job.rb:26:in `take_screenshot'
  from app/jobs/generate_website_image_job.rb:13:in `perform'
  from active_job/execution.rb:39:in `block in perform_now'
  from active_support/callbacks.rb:112:in `block in run_callbacks'
  from raven/integrations/rails/active_job.rb:18:in `capture_and_reraise_with_sentry'
  from raven/integrations/rails/active_job.rb:12:in `block (2 levels) in included'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from i18n.rb:297:in `with_locale'
  from active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from active_support/core_ext/time/zones.rb:66:in `use_zone'
  from active_job/timezones.rb:9:in `block (2 levels) in <module:Timezones>'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from active_job/logging.rb:25:in `block (4 levels) in <module:Logging>'
  from active_support/notifications.rb:180:in `block in instrument'
  from active_support/notifications/instrumenter.rb:24:in `instrument'
  from active_support/notifications.rb:180:in `instrument'
  from active_job/logging.rb:24:in `block (3 levels) in <module:Logging>'
  from active_job/logging.rb:45:in `block in tag_logger'
  from active_support/tagged_logging.rb:80:in `block in tagged'
  from active_support/tagged_logging.rb:28:in `tagged'
  from active_support/tagged_logging.rb:80:in `tagged'
  from active_job/logging.rb:45:in `tag_logger'
  from active_job/logging.rb:21:in `block (2 levels) in <module:Logging>'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from active_support/callbacks.rb:139:in `run_callbacks'
  from active_job/execution.rb:38:in `perform_now'
  from active_job/execution.rb:24:in `block in execute'
  from active_support/callbacks.rb:112:in `block in run_callbacks'
  from active_job/railtie.rb:43:in `block (4 levels) in <class:Railtie>'
  from active_support/execution_wrapper.rb:88:in `wrap'
  from active_support/reloader.rb:72:in `block in wrap'
  from active_support/execution_wrapper.rb:84:in `wrap'
  from active_support/reloader.rb:71:in `wrap'
  from active_job/railtie.rb:42:in `block (3 levels) in <class:Railtie>'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from active_support/callbacks.rb:139:in `run_callbacks'
  from active_job/execution.rb:22:in `execute'
  from active_job/queue_adapters/sidekiq_adapter.rb:42:in `perform'
  from sidekiq/processor.rb:192:in `execute_job'
  from sidekiq/processor.rb:165:in `block (2 levels) in process'
  from sidekiq/middleware/chain.rb:128:in `block in invoke'
  from raven/integrations/sidekiq.rb:9:in `call'
  from sidekiq/middleware/chain.rb:130:in `block in invoke'
  from sidekiq/middleware/chain.rb:133:in `invoke'
  from sidekiq/processor.rb:164:in `block in process'
  from sidekiq/processor.rb:137:in `block (6 levels) in dispatch'
  from sidekiq/job_retry.rb:109:in `local'
  from sidekiq/processor.rb:136:in `block (5 levels) in dispatch'
  from sidekiq/rails.rb:43:in `block in call'
  from active_support/execution_wrapper.rb:88:in `wrap'
  from active_support/reloader.rb:72:in `block in wrap'
  from active_support/execution_wrapper.rb:88:in `wrap'
  from active_support/reloader.rb:71:in `wrap'
  from sidekiq/rails.rb:42:in `call'
  from sidekiq/processor.rb:132:in `block (4 levels) in dispatch'
  from sidekiq/processor.rb:250:in `stats'
  from sidekiq/processor.rb:127:in `block (3 levels) in dispatch'
  from sidekiq/job_logger.rb:8:in `call'
  from sidekiq/processor.rb:126:in `block (2 levels) in dispatch'
  from sidekiq/job_retry.rb:74:in `global'
  from sidekiq/processor.rb:125:in `block in dispatch'
  from sidekiq/logging.rb:48:in `with_context'
  from sidekiq/logging.rb:42:in `with_job_hash_context'
  from sidekiq/processor.rb:124:in `dispatch'
  from sidekiq/processor.rb:163:in `process'
  from sidekiq/processor.rb:83:in `process_one'
  from sidekiq/processor.rb:71:in `run'
  from sidekiq/util.rb:16:in `watchdog'
  from sidekiq/util.rb:25:in `block in safe_thread'

Errno

Errno::ENOENT: No such file or directory @ apply2files - /app/.webdrivers/chromedriver
  from fileutils.rb:1321:in `chmod'
  from fileutils.rb:1321:in `chmod'
  from fileutils.rb:997:in `block in chmod'
  from fileutils.rb:996:in `each'
  from fileutils.rb:996:in `chmod'
  from zip/entry.rb:416:in `set_unix_permissions_on_path'
  from zip/entry.rb:426:in `set_extra_attributes_on_path'
  from zip/entry.rb:604:in `block (2 levels) in create_file'
  from zip/entry.rb:522:in `get_input_stream'
  from zip/entry.rb:603:in `block in create_file'
  from zip/entry.rb:602:in `open'
  from zip/entry.rb:602:in `create_file'
  from zip/entry.rb:174:in `extract'
  from zip/file.rb:303:in `extract'
  from webdrivers/system.rb:126:in `block in unzip_file'
  from zip/file.rb:100:in `open'
  from webdrivers/system.rb:121:in `unzip_file'
  from webdrivers/system.rb:93:in `decompress_file'
  from webdrivers/system.rb:74:in `block in download_file'
  from webdrivers/system.rb:64:in `chdir'
  from webdrivers/system.rb:64:in `download_file'
  from webdrivers/system.rb:55:in `download'
  from webdrivers/common.rb:99:in `update'
  from webdrivers/chromedriver.rb:119:in `block in <main>'
  from selenium/webdriver/common/service.rb:133:in `binary_path'
  from selenium/webdriver/common/service.rb:94:in `initialize'
  from selenium/webdriver/common/service.rb:41:in `new'
  from selenium/webdriver/common/service.rb:41:in `chrome'
  from selenium/webdriver/common/driver.rb:299:in `service_url'
  from selenium/webdriver/chrome/driver.rb:40:in `initialize'
  from selenium/webdriver/common/driver.rb:46:in `new'
  from selenium/webdriver/common/driver.rb:46:in `for'
  from selenium/webdriver.rb:88:in `for'
  from app/jobs/generate_website_image_job.rb:26:in `take_screenshot'
  from app/jobs/generate_website_image_job.rb:13:in `perform'
  from active_job/execution.rb:39:in `block in perform_now'
  from active_support/callbacks.rb:112:in `block in run_callbacks'
  from raven/integrations/rails/active_job.rb:18:in `capture_and_reraise_with_sentry'
  from raven/integrations/rails/active_job.rb:12:in `block (2 levels) in included'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from i18n.rb:297:in `with_locale'
  from active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from active_support/core_ext/time/zones.rb:66:in `use_zone'
  from active_job/timezones.rb:9:in `block (2 levels) in <module:Timezones>'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from active_job/logging.rb:25:in `block (4 levels) in <module:Logging>'
  from active_support/notifications.rb:180:in `block in instrument'
  from active_support/notifications/instrumenter.rb:24:in `instrument'
  from active_support/notifications.rb:180:in `instrument'
  from active_job/logging.rb:24:in `block (3 levels) in <module:Logging>'
  from active_job/logging.rb:45:in `block in tag_logger'
  from active_support/tagged_logging.rb:80:in `block in tagged'
  from active_support/tagged_logging.rb:28:in `tagged'
  from active_support/tagged_logging.rb:80:in `tagged'
  from active_job/logging.rb:45:in `tag_logger'
  from active_job/logging.rb:21:in `block (2 levels) in <module:Logging>'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from active_support/callbacks.rb:139:in `run_callbacks'
  from active_job/execution.rb:38:in `perform_now'
  from active_job/execution.rb:24:in `block in execute'
  from active_support/callbacks.rb:112:in `block in run_callbacks'
  from active_job/railtie.rb:43:in `block (4 levels) in <class:Railtie>'
  from active_support/execution_wrapper.rb:88:in `wrap'
  from active_support/reloader.rb:72:in `block in wrap'
  from active_support/execution_wrapper.rb:84:in `wrap'
  from active_support/reloader.rb:71:in `wrap'
  from active_job/railtie.rb:42:in `block (3 levels) in <class:Railtie>'
  from active_support/callbacks.rb:121:in `instance_exec'
  from active_support/callbacks.rb:121:in `block in run_callbacks'
  from active_support/callbacks.rb:139:in `run_callbacks'
  from active_job/execution.rb:22:in `execute'
  from active_job/queue_adapters/sidekiq_adapter.rb:42:in `perform'
  from sidekiq/processor.rb:192:in `execute_job'
  from sidekiq/processor.rb:165:in `block (2 levels) in process'
  from sidekiq/middleware/chain.rb:128:in `block in invoke'
  from raven/integrations/sidekiq.rb:9:in `call'
  from sidekiq/middleware/chain.rb:130:in `block in invoke'
  from sidekiq/middleware/chain.rb:133:in `invoke'
  from sidekiq/processor.rb:164:in `block in process'
  from sidekiq/processor.rb:137:in `block (6 levels) in dispatch'
  from sidekiq/job_retry.rb:109:in `local'
  from sidekiq/processor.rb:136:in `block (5 levels) in dispatch'
  from sidekiq/rails.rb:43:in `block in call'
  from active_support/execution_wrapper.rb:88:in `wrap'
  from active_support/reloader.rb:72:in `block in wrap'
  from active_support/execution_wrapper.rb:88:in `wrap'
  from active_support/reloader.rb:71:in `wrap'
  from sidekiq/rails.rb:42:in `call'
  from sidekiq/processor.rb:132:in `block (4 levels) in dispatch'
  from sidekiq/processor.rb:250:in `stats'
  from sidekiq/processor.rb:127:in `block (3 levels) in dispatch'
  from sidekiq/job_logger.rb:8:in `call'
  from sidekiq/processor.rb:126:in `block (2 levels) in dispatch'
  from sidekiq/job_retry.rb:74:in `global'
  from sidekiq/processor.rb:125:in `block in dispatch'
  from sidekiq/logging.rb:48:in `with_context'
  from sidekiq/logging.rb:42:in `with_job_hash_context'
  from sidekiq/processor.rb:124:in `dispatch'
  from sidekiq/processor.rb:163:in `process'
  from sidekiq/processor.rb:83:in `process_one'
  from sidekiq/processor.rb:71:in `run'
  from sidekiq/util.rb:16:in `watchdog'
  from sidekiq/util.rb:25:in `block in safe_thread'

[twalpole]

You need to either run the update process (directly through code or via the rake command) before starting the worker processes, or specify a different webdrivers install dir for each process.

[titusfortner]

This is a duplicate of #77

If that solution won't work for your use case, or you have a suggestion for an alternate approach, let us know.

[brenogazzola]

I've taken a look at #77 now that you pointed it, and the solution is to set a different file_path for each processes using the env variable ENV['TEST_ENV_NUMBER']

I'm not sure how I'd do that in a production environment, with Sidekiq though. Each worker dyno will have 20 sidekiq processes running, which all share the same env variables, so I can't rely on that exact solution.

I could try generating a random directory when the job is run, but that means that every time I'd get a different folder, and therefore I'd always have to download the driver. I'm going to take a look if it's possible for each Sidekiq to have their own custom variables, but that seems a bit hacky to me, and prone to problems.

84 solved the download problem, but as mentioned there's still collisions when writing the final binary.

There was a mention of locking the file during download, so wouldn't it be possible to lock when writing the final binary instead? Then when other processes tried to write and got locked they'd automatically use another directory to prevent any deadlocks, using that binary at the time, before reverting to use the original binary (or maybe just keeping using their alternate binaries)?

[twalpole]

If you are going to use a different install dir for each process you can use the pid to generate unique directories, however is there a specific reason you can't just run Webdrivers::Chromedriver.update before forking the processes?

[brenogazzola]

No there isn't... I went through the source code but didn't understand how calling update on the jobs would help a race condition. But now that your comment made me actually stop to think about it, I guess I could just throw it in an initializer which would force a download while Sidekiq is booting and before it had a chance to start its workers.

I'll try that. Thanks.

[brenogazzola]

Putting the call to update in an initializer breaks Heroku's build process since ENV['GOOGLE_CHROME_BIN'] is not set at that moment yet. Putting it in the configure_server block of Sidekiq solved the problem.

Sidekiq.configure_server do |config|
  Webdrivers::Chromedriver.update
end

If anyone needs to use webdrivers with sidekiq in production, this should solve the problem of every deploy causing multiple exceptions as all sidekiq processes try to download the driver at the same time.