Lighthouse has a new layout. Prefer the old one? Return to the old layout, and switch back any time from the link at the top of each page.

This project is archived and is in readonly mode.

Fragment cache logging fails in 3.0 when fragment path contains printf chars, e.g. "%A"

#5570

Given a (reasonable) fragment path such as:

views/localhost:3000/action?date=2010-08-23+15%3A30%3A00

Rails reports the following error:

Could not log "exist_fragment?.action_controller" event. ArgumentError: malformed format string - %A

Judging by the code in fragment.rb, it looks like the key is passed to the instrumenter as part of the payload -- should the key perhaps be escaped somehow before handing it to the instrumenter, or is it incorrect that the instrumenter is using the payload in a printf way?

Reported by Steve Purcell · September 7th, 2010 @ 11:36 AM

State: resolved
Milestone: none
Assigned to: Santiago Pastorino Santiago Pastorino
Importance: Low

Activity

  1. David Trasbo
    David Trasbo

    Could you please provide the code that causes this issue?

    September 7th, 2010 @ 12:37 PM

  2. Steve Purcell
    Steve Purcell

    Sure.

    Example view code would look like this:

    cache(:foo => "key with spaces") do
      ... render something ...
    end
    

    where #cache is presumably ActionView::Helpers::CacheHelper#cache

    -Steve

    September 7th, 2010 @ 01:27 PM

  3. David Trasbo
    David Trasbo
    • State changed from new to resolved
    • Importance changed from to Low

    This issue is gone in Rails master:

    Warmup:

    Started GET "/people" for 127.0.0.1 at 2010-09-20 20:21:45 +0200
      Processing by PeopleController#index as HTML
    Exist fragment? views/localhost:3000/people?foo=key+with+spaces (0.1ms)
    Write fragment views/localhost:3000/people?foo=key+with+spaces (3.4ms)
    Rendered people/index.html.erb within layouts/application (6.6ms)
    Completed 200 OK in 10ms (Views: 9.8ms | ActiveRecord: 0.0ms)
    cache: [GET /javascripts/prototype.js?1285006555] miss
    cache: [GET /javascripts/dragdrop.js?1285006555] miss
    cache: [GET /javascripts/effects.js?1285006555] miss
    cache: [GET /javascripts/controls.js?1285006555] miss
    cache: [GET /javascripts/rails.js?1285006555] miss
    cache: [GET /javascripts/application.js?1285006555] miss
    cache: [GET /favicon.ico] miss
    cache: [GET /people] miss
    

    After warmup:

    Started GET "/people" for 127.0.0.1 at 2010-09-20 20:22:21 +0200
      Processing by PeopleController#index as HTML
    Exist fragment? views/localhost:3000/people?foo=key+with+spaces (0.2ms)
    Read fragment views/localhost:3000/people?foo=key+with+spaces (0.0ms)
    Rendered people/index.html.erb within layouts/application (2.9ms)
    Completed 200 OK in 6ms (Views: 5.9ms | ActiveRecord: 0.0ms)
    cache: [GET /javascripts/prototype.js?1285006555] miss
    cache: [GET /javascripts/effects.js?1285006555] miss
    cache: [GET /javascripts/dragdrop.js?1285006555] miss
    cache: [GET /javascripts/controls.js?1285006555] miss
    cache: [GET /javascripts/rails.js?1285006555] miss
    cache: [GET /javascripts/application.js?1285006555] miss
    cache: [GET /favicon.ico] miss
    

    September 20th, 2010 @ 07:25 PM

  4. Steve Purcell
    Steve Purcell

    Hmm, I think that the example given should have used "key:with:colons" rather than "key with spaces", since it looks like the problematic "%3A" was the result of url-escaping colons, not spaces -- sorry.

    David: in the light of that mistake on my part, you might want to double-check that it's indeed working fine in Rails Master.

    September 20th, 2010 @ 08:41 PM

  5. David Trasbo
    David Trasbo
    • State changed from resolved to open

    Steve,

    Ah, ok. No problem. Reopening this and putting it on my follow-up list. Will most likely have a look at this again tomorrow.

    September 20th, 2010 @ 08:44 PM

  6. David Trasbo
    David Trasbo

    You're right, Steve! Was able to duplicate this issue on master:

    Warmup:

    Started GET "/people" for 127.0.0.1 at 2010-09-21 07:07:24 +0200
      Processing by PeopleController#index as HTML
    Could not log "exist_fragment?.action_controller" event. ArgumentError: too few arguments
    Could not log "write_fragment.action_controller" event. ArgumentError: too few arguments
    Rendered people/index.html.erb within layouts/application (6.8ms)
    Completed 200 OK in 10ms (Views: 9.8ms | ActiveRecord: 0.0ms)
    cache: [GET /javascripts/prototype.js?1285045419] miss
    cache: [GET /javascripts/effects.js?1285045419] miss
    cache: [GET /javascripts/dragdrop.js?1285045419] miss
    cache: [GET /javascripts/controls.js?1285045419] miss
    cache: [GET /javascripts/rails.js?1285045419] miss
    cache: [GET /javascripts/application.js?1285045419] miss
    cache: [GET /favicon.ico] miss
    cache: [GET /people] miss
    

    After warmup:

    Started GET "/people" for 127.0.0.1 at 2010-09-21 07:07:41 +0200
      Processing by PeopleController#index as HTML
    Could not log "exist_fragment?.action_controller" event. ArgumentError: too few arguments
    Could not log "read_fragment.action_controller" event. ArgumentError: too few arguments
    Rendered people/index.html.erb within layouts/application (3.3ms)
    Completed 200 OK in 7ms (Views: 6.2ms | ActiveRecord: 0.0ms)
    cache: [GET /javascripts/dragdrop.js?1285045419] miss
    cache: [GET /javascripts/effects.js?1285045419] miss
    cache: [GET /javascripts/prototype.js?1285045419] miss
    cache: [GET /javascripts/controls.js?1285045419] miss
    cache: [GET /javascripts/rails.js?1285045419] miss
    cache: [GET /javascripts/application.js?1285045419] miss
    

    I might investigate how to solve this later today.

    September 21st, 2010 @ 06:10 AM

  7. Marjan Krekoten'
  8. David Trasbo
    David Trasbo

    Marjon,

    +1 for the fix, but -1 for the tests. I think you should make a separate test for percentage signs, to make sure people know they're there for a reason.

    September 22nd, 2010 @ 03:04 PM

  9. Marjan Krekoten'
    Marjan Krekoten'

    Ok, I'll fix tests soon. Thx for response.

    September 22nd, 2010 @ 03:20 PM

  10. Marjan Krekoten'
  11. Repository
  12. Skully
    Skully

    Not sure if i should open a new ticket but with rails 3.0.7 i am getting the following error:

    Could not log "read_fragment.action_controller" event. ArgumentError: malformed format string - %F
    

    with the following code:

    cache({:element => graph.cache_key, :lang => I18n.locale.to_s})
    

    Graph is a normal model.

    April 24th, 2011 @ 03:26 PM

  13. Steve Purcell
    Steve Purcell

    Indeed. I still get the same error messages too. They didn't ever go away for me with any particular Rails release, so I'm not convinced that the fix was complete.

    April 24th, 2011 @ 04:49 PM

  14. af001
    af001

    私の中で、総合評価のとっても低いアバアバクロホリスタークロ銀座店。アバクロは大好きなんですけどね。一昨日の東京駅付近での打ち合わせの後、散歩がてら久々に行ってきました。そしたらビックリ!相変わらアバクロず、踊っているだけの店員さんとかもいましたが、

    May 5th, 2011 @ 02:56 AM