This project is archived and is in readonly mode.

#5570 ✓resolved
Steve Purcell

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

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

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?

Comments and changes to this ticket

  • David Trasbo

    David Trasbo September 7th, 2010 @ 12:37 PM

    Could you please provide the code that causes this issue?

  • Steve Purcell

    Steve Purcell September 7th, 2010 @ 01:27 PM

    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

  • David Trasbo

    David Trasbo September 20th, 2010 @ 07:25 PM

    • 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
  • Steve Purcell

    Steve Purcell September 20th, 2010 @ 08:41 PM

    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.

  • David Trasbo

    David Trasbo September 20th, 2010 @ 08:44 PM

    • 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.

  • David Trasbo

    David Trasbo September 21st, 2010 @ 06:10 AM

    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.

  • Marjan Krekoten'

    Marjan Krekoten' September 21st, 2010 @ 09:23 AM

    • Assigned user set to “Santiago Pastorino”
  • David Trasbo

    David Trasbo September 22nd, 2010 @ 03:04 PM

    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.

  • Marjan Krekoten'

    Marjan Krekoten' September 22nd, 2010 @ 03:20 PM

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

  • Marjan Krekoten'

    Marjan Krekoten' September 22nd, 2010 @ 09:20 PM

    • no changes were found...
  • Repository

    Repository September 25th, 2010 @ 10:07 AM

    • State changed from “open” to “resolved”

    (from [8639c10a40604cee2f3d412470c2960712fdc809]) Fix logging when cache key contains % sign [#5570 state:resolved]

    Signed-off-by: José Valim jose.valim@gmail.com
    http://github.com/rails/rails/commit/8639c10a40604cee2f3d412470c296...

  • Skully

    Skully April 24th, 2011 @ 03:26 PM

    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.

  • Steve Purcell

    Steve Purcell April 24th, 2011 @ 04:49 PM

    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.

  • af001

    af001 May 5th, 2011 @ 02:56 AM

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

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile »

<h2 style="font-size: 14px">Tickets have moved to Github</h2>

The new ticket tracker is available at <a href="https://github.com/rails/rails/issues">https://github.com/rails/rails/issues</a>

People watching this ticket

Attachments

Tags

Referenced by

Pages