decode_www_form_component complains about "invalid %-encoding" in Rails Refinery App

Question

TLDR; in certain unlikely cases (related to chars like á and &) the refinery cache (tmp/cache/) becomes corrupt preventing pages from being updated.

I haven't found a long term solution for this but managed to fix it for now (see fix section below). I'm posting what I've found since googling didn't provide anything relevant.

Update a page via the admin interface in refinery failed with this error:

ArgumentError (invalid %-encoding (fbGFuZ3VhZ2VfYW1vbmdfbm9uX01fb3JpX05ld19hbm5vdGF0ZWQucGRmIl1d%2Fde%2520Bres%2520-%25202008%2520-%2520Planning%2520for%2520Tolerability%2520Promoting%2520positive%2520attitudes%2520and%2520behaviours%2520towards%2520the%2520M%25c4%/2581ori%2520language%2520among%2520non-M%25c4%2581ori%2520New-annotated.pdf%3F)):
  /opt/rbenv/versions/2.1.2/lib/ruby/2.1.0/uri/common.rb:901:in `decode_www_form_component'
  rack (1.4.5) lib/rack/utils.rb:41:in `unescape'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:148:in `file_path_key'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:72:in `block (2 levels) in delete_matched'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:173:in `call'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:173:in `block in search_dir'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:167:in `foreach'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:167:in `search_dir'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:171:in `block in search_dir'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:167:in `foreach'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:167:in `search_dir'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:171:in `block in search_dir'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:167:in `foreach'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:167:in `search_dir'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:171:in `block in search_dir'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:167:in `foreach'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:167:in `search_dir'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:171:in `block in search_dir'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:167:in `foreach'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:167:in `search_dir'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:71:in `block in delete_matched'
  activesupport (3.2.18) lib/active_support/cache.rb:520:in `instrument'
  activesupport (3.2.18) lib/active_support/cache/file_store.rb:69:in `delete_matched'
  refinerycms-pages (2.1.2) lib/refinery/pages/caching.rb:29:in `clear_caching!'
  refinerycms-pages (2.1.2) lib/refinery/pages/caching.rb:12:in `expire!'
  refinerycms-pages (2.1.2) app/sweepers/refinery/pages/page_sweeper.rb:24:in `expire_cache!'
  refinerycms-pages (2.1.2) app/sweepers/refinery/pages/page_sweeper.rb:7:in `after_save'
  activemodel (3.2.18) lib/active_model/observing.rb:231:in `update'
  activerecord (3.2.18) lib/active_record/observer.rb:114:in `block (2 levels) in define_callbacks'
  activesupport (3.2.18) lib/active_support/callbacks.rb:472:in `_run__3016756163475691774__save__4349902776367396713__callbacks'
  activesupport (3.2.18) lib/active_support/callbacks.rb:405:in `__run_callback'
  activesupport (3.2.18) lib/active_support/callbacks.rb:385:in `_run_save_callbacks'
  activesupport (3.2.18) lib/active_support/callbacks.rb:81:in `run_callbacks'
  activerecord (3.2.18) lib/active_record/callbacks.rb:264:in `create_or_update'
  activerecord (3.2.18) lib/active_record/persistence.rb:84:in `save'
  activerecord (3.2.18) lib/active_record/validations.rb:50:in `save'
  activerecord (3.2.18) lib/active_record/attribute_methods/dirty.rb:22:in `save'
  activerecord (3.2.18) lib/active_record/transactions.rb:259:in `block (2 levels) in save'
  activerecord (3.2.18) lib/active_record/transactions.rb:313:in `block in with_transaction_returning_status'
  activerecord (3.2.18) lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'
  activerecord (3.2.18) lib/active_record/transactions.rb:208:in `transaction'
  activerecord (3.2.18) lib/active_record/transactions.rb:311:in `with_transaction_returning_status'
  activerecord (3.2.18) lib/active_record/transactions.rb:259:in `block in save'
  activerecord (3.2.18) lib/active_record/transactions.rb:270:in `rollback_active_record_state!'
  activerecord (3.2.18) lib/active_record/transactions.rb:258:in `save'
  activerecord (3.2.18) lib/active_record/persistence.rb:217:in `block in update_attributes'
  activerecord (3.2.18) lib/active_record/transactions.rb:313:in `block in with_transaction_returning_status'
  activerecord (3.2.18) lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'
  activerecord (3.2.18) lib/active_record/transactions.rb:208:in `transaction'
  activerecord (3.2.18) lib/active_record/transactions.rb:311:in `with_transaction_returning_status'
  activerecord (3.2.18) lib/active_record/persistence.rb:215:in `update_attributes'
  refinerycms-pages (2.1.2) app/controllers/refinery/admin/pages_controller.rb:29:in `update'
  actionpack (3.2.18) lib/action_controller/metal/implicit_render.rb:4:in `send_action'
  actionpack (3.2.18) lib/abstract_controller/base.rb:167:in `process_action'
  actionpack (3.2.18) lib/action_controller/metal/rendering.rb:10:in `process_action'
  actionpack (3.2.18) lib/abstract_controller/callbacks.rb:18:in `block in process_action'
  activesupport (3.2.18) lib/active_support/callbacks.rb:514:in `block in _run__3682042010644646627__process_action__616700943181112013__callbacks'
  activesupport (3.2.18) lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_506'
  activesupport (3.2.18) lib/active_support/callbacks.rb:326:in `around'
  activesupport (3.2.18) lib/active_support/callbacks.rb:310:in `_callback_around_395'
  activesupport (3.2.18) lib/active_support/callbacks.rb:214:in `_conditional_callback_around_506'
  activesupport (3.2.18) lib/active_support/callbacks.rb:502:in `_run__3682042010644646627__process_action__616700943181112013__callbacks'
  activesupport (3.2.18) lib/active_support/callbacks.rb:405:in `__run_callback'
  activesupport (3.2.18) lib/active_support/callbacks.rb:385:in `_run_process_action_callbacks'
  activesupport (3.2.18) lib/active_support/callbacks.rb:81:in `run_callbacks'
  actionpack (3.2.18) lib/abstract_controller/callbacks.rb:17:in `process_action'
  actionpack (3.2.18) lib/action_controller/metal/rescue.rb:29:in `process_action'
  actionpack (3.2.18) lib/action_controller/metal/instrumentation.rb:30:in `block in process_action'
  activesupport (3.2.18) lib/active_support/notifications.rb:123:in `block in instrument'
  activesupport (3.2.18) lib/active_support/notifications/instrumenter.rb:20:in `instrument'
  activesupport (3.2.18) lib/active_support/notifications.rb:123:in `instrument'
  actionpack (3.2.18) lib/action_controller/metal/instrumentation.rb:29:in `process_action'
  actionpack (3.2.18) lib/action_controller/metal/params_wrapper.rb:207:in `process_action'
  activerecord (3.2.18) lib/active_record/railties/controller_runtime.rb:18:in `process_action'
  actionpack (3.2.18) lib/abstract_controller/base.rb:121:in `process'
  actionpack (3.2.18) lib/abstract_controller/rendering.rb:45:in `process'
  actionpack (3.2.18) lib/action_controller/metal.rb:203:in `dispatch'
  actionpack (3.2.18) lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
  actionpack (3.2.18) lib/action_controller/metal.rb:246:in `block in action'
  actionpack (3.2.18) lib/action_dispatch/routing/route_set.rb:73:in `call'
  actionpack (3.2.18) lib/action_dispatch/routing/route_set.rb:73:in `dispatch'
  actionpack (3.2.18) lib/action_dispatch/routing/route_set.rb:36:in `call'
  journey (1.0.4) lib/journey/router.rb:68:in `block in call'
  journey (1.0.4) lib/journey/router.rb:56:in `each'
  journey (1.0.4) lib/journey/router.rb:56:in `call'
  actionpack (3.2.18) lib/action_dispatch/routing/route_set.rb:608:in `call'
  railties (3.2.18) lib/rails/engine.rb:484:in `call'
  railties (3.2.18) lib/rails/railtie/configurable.rb:30:in `method_missing'
  journey (1.0.4) lib/journey/router.rb:68:in `block in call'
  journey (1.0.4) lib/journey/router.rb:56:in `each'
  journey (1.0.4) lib/journey/router.rb:56:in `call'
  actionpack (3.2.18) lib/action_dispatch/routing/route_set.rb:608:in `call'
  warden (1.2.3) lib/warden/manager.rb:35:in `block in call'
  warden (1.2.3) lib/warden/manager.rb:34:in `catch'
  warden (1.2.3) lib/warden/manager.rb:34:in `call'
  actionpack (3.2.18) lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
  rack (1.4.5) lib/rack/etag.rb:23:in `call'
  rack (1.4.5) lib/rack/conditionalget.rb:35:in `call'
  actionpack (3.2.18) lib/action_dispatch/middleware/head.rb:14:in `call'
  actionpack (3.2.18) lib/action_dispatch/middleware/params_parser.rb:21:in `call'
  actionpack (3.2.18) lib/action_dispatch/middleware/flash.rb:242:in `call'
  rack (1.4.5) lib/rack/session/abstract/id.rb:210:in `context'
  rack (1.4.5) lib/rack/session/abstract/id.rb:205:in `call'
  actionpack (3.2.18) lib/action_dispatch/middleware/cookies.rb:341:in `call'
  dragonfly (0.9.15) lib/dragonfly/cookie_monster.rb:9:in `call'
  activerecord (3.2.18) lib/active_record/query_cache.rb:64:in `call'
  activerecord (3.2.18) lib/active_record/connection_adapters/abstract/connection_pool.rb:479:in `call'
  actionpack (3.2.18) lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
  activesupport (3.2.18) lib/active_support/callbacks.rb:405:in `_run__739920887154609660__call__4349902776367396713__callbacks'
  activesupport (3.2.18) lib/active_support/callbacks.rb:405:in `__run_callback'
  activesupport (3.2.18) lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
  activesupport (3.2.18) lib/active_support/callbacks.rb:81:in `run_callbacks'
  actionpack (3.2.18) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  actionpack (3.2.18) lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
  actionpack (3.2.18) lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
  actionpack (3.2.18) lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
  railties (3.2.18) lib/rails/rack/logger.rb:32:in `call_app'
  railties (3.2.18) lib/rails/rack/logger.rb:16:in `block in call'
  activesupport (3.2.18) lib/active_support/tagged_logging.rb:22:in `tagged'
  railties (3.2.18) lib/rails/rack/logger.rb:16:in `call'
  actionpack (3.2.18) lib/action_dispatch/middleware/request_id.rb:22:in `call'
  rack (1.4.5) lib/rack/methodoverride.rb:21:in `call'
  rack (1.4.5) lib/rack/runtime.rb:17:in `call'
  activesupport (3.2.18) lib/active_support/cache/strategy/local_cache.rb:72:in `call'
  rack (1.4.5) lib/rack/lock.rb:15:in `call'
  rack-cache (1.2) lib/rack/cache/context.rb:136:in `forward'
  rack-cache (1.2) lib/rack/cache/context.rb:143:in `pass'
  rack-cache (1.2) lib/rack/cache/context.rb:155:in `invalidate'
  rack-cache (1.2) lib/rack/cache/context.rb:71:in `call!'
  rack-cache (1.2) lib/rack/cache/context.rb:51:in `call'
  railties (3.2.18) lib/rails/engine.rb:484:in `call'
  railties (3.2.18) lib/rails/application.rb:231:in `call'
  railties (3.2.18) lib/rails/railtie/configurable.rb:30:in `method_missing'
  unicorn (4.8.2) lib/unicorn/http_server.rb:572:in `process_client'
  unicorn (4.8.2) lib/unicorn/http_server.rb:666:in `worker_loop'
  unicorn (4.8.2) lib/unicorn/http_server.rb:521:in `spawn_missing_workers'
  unicorn (4.8.2) lib/unicorn/http_server.rb:532:in `maintain_worker_count'
  unicorn (4.8.2) lib/unicorn/http_server.rb:290:in `join'
  unicorn (4.8.2) bin/unicorn_rails:209:in `<top (required)>'
  /home/deploy/mlc/shared/bundle/ruby/2.1.0/bin/unicorn_rails:23:in `load'
  /home/deploy/mlc/shared/bundle/ruby/2.1.0/bin/unicorn_rails:23:in `<main>'

The relevant parts are:

activesupport (3.2.18) lib/active_support/cache/file_store.rb:69:in `delete_matched'
refinerycms-pages (2.1.2) lib/refinery/pages/caching.rb:29:in `clear_caching!'
refinerycms-pages (2.1.2) lib/refinery/pages/caching.rb:12:in `expire!'
refinerycms-pages (2.1.2) app/sweepers/refinery/pages/page_sweeper.rb:24:in `expire_cache!'
refinerycms-pages (2.1.2) app/sweepers/refinery/pages/page_sweeper.rb:7:in `after_save'

...

refinerycms-pages (2.1.2) app/controllers/refinery/admin/pages_controller.rb:29:in `update'

Summary:

• update is called
• refinery-hooks clean cache after update
• there are bad file names processed by this
• rails calls URI.decode_www_form_component on the file names
• explosive magical fun!

Notes:

• This applied to version 2.1.0 of refinery I haven't had a chance to test it in newer versions.
• the file in question is here: tmp/cache/BA1/EDA/http%3A%2F%2Fwhakarauora.org.nz%2Fsystem%2Fresources%2FW1siZiIsIjIwMTQvMTAvMDYvMTdfMDVfNTBfNzkzX2RlX0JyZXNfMjAwOF9QbGFubmluZ19mb3JfVG9sZXJhYmlsaXR5X1Byb21vdGluZ19wb3NpdGl2ZV9hdHRpdHVkZXNfYW5kX2JlaGF2aW91cnNfdG93YXJkc190aGVfTV9vcml/fbGFuZ3VhZ2VfYW1vbmdfbm9uX01fb3JpX05ld19hbm5vdGF0ZWQucGRmIl1d%2Fde%2520Bres%2520-%25202008%2520-%2520Planning%2520for%2520Tolerability%2520Promoting%2520positive%2520attitudes%2520and%2520behaviours%2520towards%2520the%2520M%25c4%/2581ori%2520language%2520among%2520non-M%25c4%2581ori%2520New-annotated.pdf%3F
• this seems to be the record of an http request
• these files were pre-existing (not created by the update call)
• the problem seems to be
  • a percentage encoding call was made (% -> %25)
  • the huge filename was written to a dir ...the%2520M%25c4%/
  • this split across the three characters of the percentage encoding (%25 in this case)
  • which caused problems with URI.decode_www_form_component (URI.unescape works though)
• this means having lots of non-ASCII or punctuation in your cache-files—having a non-english language say—increases your chances of having this corner case happen.

Fix:

I fixed this by sshing to the box, finding offending dirs with find RAILS_DIRNAME/tmp/cache -name '*%' -or -name '*%?', and then deleting them. This fixes the problem for now, but may need to be repeated later.

Answer 1

Changing the filename to a short name and using underscores instead of blank spaces worked for me after running rake tmp:cache:clear

Answer 2

i've found solution for this trouble. maybe it's not very beautiful, but it's worked for me. in environments/production.rb change config.action_controller.perform_caching to false