Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Asset#mtime was deprecated and not the correct value #197

Merged
merged 2 commits into from
Dec 5, 2015

Conversation

schneems
Copy link
Member

@schneems schneems commented Dec 4, 2015

This change pulls mtime from the environment stat cache instead of relying on the asset object. Reference: 16ccffc#commitcomment-14779288

@rails-bot
Copy link

warning Warning warning

  • Pull requests are usually filed against the master branch for this repo, but this one is against 3.x. Please double check that you specified the right target!

@schneems
Copy link
Member Author

schneems commented Dec 4, 2015

@fxn I'm not sure that Zlib::GzipWriter#mtime is doing the right thing. Or not doing what we expected it to. From the docs:

http://ruby-doc.org/stdlib-2.2.3/libdoc/zlib/rdoc/Zlib/GzipWriter.html#method-i-mtime-3D

Specify the modification time (mtime) in the gzip header. Using a Fixnum or Integer

But it doesn't actually change the mtime of the file:

$ ls -la
-rw-r--r--  1 richardschneeman  staff     3604 Oct 14 10:52 codetriage-logo-0cfe6038dec5f88690be415b08d31413a6351634cce2412b9433f8a8ef2ea307.svg
-rw-r--r--  1 richardschneeman  staff     1466 Dec  4 10:13 codetriage-logo-0cfe6038dec5f88690be415b08d31413a6351634cce2412b9433f8a8ef2ea307.svg.gz

Aside from that passing comment in the nginx docs you sent I don't know where the desired behavior is specified. Does it matter that the gzip file has a different mtime than the original file? Is this code doing the correct thing, but my test and my interpretations are wrong?

@schneems
Copy link
Member Author

schneems commented Dec 4, 2015

I updated with a better test where we are verifying the header value, however i'm still not totally convinced that we are doing the right thing. Or even testing the right thing. I've not done extensive work with gzip files before this.

@schneems
Copy link
Member Author

schneems commented Dec 4, 2015

Now that i'm looking closer i'm seeing some unrelated behavior that I don't quite understand.

I'm removing the cache and public directory and generating assets:

$ rm -rf public/assets/ tmp/cache/; time RAILS_ENV=production bundle exec rake assets:precompile

So all the mtimes should be on the same day (December 4) but they aren't:

$ ls -la public/assets
total 5912
drwxr-xr-x  13 richardschneeman  staff      442 Dec  4 10:45 .
drwxr-xr-x   9 richardschneeman  staff      306 Dec  4 10:45 ..
-rw-r--r--   1 richardschneeman  staff     3007 Dec  4 10:45 .sprockets-manifest-41cc443057a47878dc92a852e992b981.json
-rw-r--r--   1 richardschneeman  staff    24521 Nov 30 12:14 application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css
-rw-r--r--   1 richardschneeman  staff     5018 Dec  4 10:45 application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css.gz

Note that application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css has a time of november.

@fxn
Copy link
Member

fxn commented Dec 4, 2015

@schneems interesting!

@rafaelfranca
Copy link
Member

Isn't the most recent mtime of the files that composes application.css?

On Fri, Dec 4, 2015, 14:55 Xavier Noria notifications@github.com wrote:

@schneems https://github.com/schneems interesting!


Reply to this email directly or view it on GitHub
#197 (comment).

@fxn
Copy link
Member

fxn commented Dec 4, 2015

@rafaelfranca that would make sense.

@schneems
Copy link
Member Author

schneems commented Dec 4, 2015

That kinda makes sense, I wonder why the mtime wouldn't just be when the file was written?

$ ls -la app/assets/stylesheets/
total 16
drwxr-xr-x   7 richardschneeman  staff   238 Oct 16 16:53 .
drwxr-xr-x   6 richardschneeman  staff   204 Nov  5 11:58 ..
-rw-r--r--   1 richardschneeman  staff   128 Oct 14 10:52 application.scss
drwxr-xr-x  10 richardschneeman  staff   340 Oct 14 10:52 base
drwxr-xr-x  18 richardschneeman  staff   612 Nov 30 12:14 components
drwxr-xr-x   5 richardschneeman  staff   170 Oct 15 11:05 layout
-rw-r--r--   1 richardschneeman  staff  1205 Sep 22  2014 pagination.css

Looks like the components/ folder was last changed in November, so that why it was generated with a november mtime.

In 3.x this change comes here

File.utime(mtime, mtime, filename)
. Looks like behavior is different between 3.x and master as Asset no longer holds mtime on master. I'm not sure if that logic was preserved an moved somewhere else.

Back to original problem

I would assume that setting the "header" mtime would mean that when you unzip the file it would have the mtime of we specified instead of when it was written too disk. But...

$ rm -rf public/assets/ tmp/cache/; time RAILS_ENV=production bundle exec rake assets:precompile
I, [2015-12-04T12:33:31.086482 #72303]  INFO -- : Writing /Users/richardschneeman/Documents/projects/codetriage/public/assets/application-c4dfdc831b963c426131ae50f1facfbe6de899ad7f860fb7758b0706ab230e7a.js
I, [2015-12-04T12:33:31.222794 #72303]  INFO -- : Writing /Users/richardschneeman/Documents/projects/codetriage/public/assets/application-c4dfdc831b963c426131ae50f1facfbe6de899ad7f860fb7758b0706ab230e7a.js.gz
I, [2015-12-04T12:33:31.271428 #72303]  INFO -- : Writing /Users/richardschneeman/Documents/projects/codetriage/public/assets/codetriage-logo-ad2190ad2f0e17830f721e77e975e9169739a525e59d05c11be55f5670b1a0b9.ai
I, [2015-12-04T12:33:31.317299 #72303]  INFO -- : Writing /Users/richardschneeman/Documents/projects/codetriage/public/assets/codetriage-logo-8bd6f3acd553eccf0053726b0bcdb63415edb5a2533af457ef2658dea31824ac.eps
I, [2015-12-04T12:33:31.344145 #72303]  INFO -- : Writing /Users/richardschneeman/Documents/projects/codetriage/public/assets/codetriage-logo-9b09fc0e15b5bc712d1a3dc274d241926ca1fe057fed1a15035ba0af07157628.png
I, [2015-12-04T12:33:31.353787 #72303]  INFO -- : Writing /Users/richardschneeman/Documents/projects/codetriage/public/assets/codetriage-logo-0cfe6038dec5f88690be415b08d31413a6351634cce2412b9433f8a8ef2ea307.svg
I, [2015-12-04T12:33:31.355103 #72303]  INFO -- : Writing /Users/richardschneeman/Documents/projects/codetriage/public/assets/codetriage-logo-0cfe6038dec5f88690be415b08d31413a6351634cce2412b9433f8a8ef2ea307.svg.gz
I, [2015-12-04T12:33:36.441525 #72303]  INFO -- : Writing /Users/richardschneeman/Documents/projects/codetriage/public/assets/application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css
I, [2015-12-04T12:33:36.442098 #72303]  INFO -- : Writing /Users/richardschneeman/Documents/projects/codetriage/public/assets/application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css.gz
I, [2015-12-04T12:33:37.500082 #72303]  INFO -- : Writing /Users/richardschneeman/Documents/projects/codetriage/public/assets/normalize-rails/normalize-f7978b7258ff8172fb5553402664fdded2759efb041e94dce212e4d7cc914c13.css
I, [2015-12-04T12:33:37.500742 #72303]  INFO -- : Writing /Users/richardschneeman/Documents/projects/codetriage/public/assets/normalize-rails/normalize-f7978b7258ff8172fb5553402664fdded2759efb041e94dce212e4d7cc914c13.css.gz

Looking at application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css.gz we would expect when it is unzipped to have the same mtime of application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css yet

We view the original mtimes

$ ls -la public/assets/ | grep css
-rw-r--r--   1 richardschneeman  staff    24521 Nov 30 12:14 application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css
-rw-r--r--   1 richardschneeman  staff     5018 Dec  4 12:33 application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css.gz

November 30 is the mtime we are shooting for. Delete the css file and unzip css.gz file:

$ rm public/assets/application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css
$ gzip -d public/assets/application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css.gz
$ ls -la public/assets/ | grep css
-rw-r--r--   1 richardschneeman  staff    24521 Dec  4 12:33 application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css

We are still seeing a December 4th mtime, so even if we are setting the mtime header correctly, it doesn't do what we want.

I wasn't sure if we were setting the correct value. I added some debug statements to verify we are setting the right mtime inside of gzip.rb, and it looks right:

"/Users/richardschneeman/Documents/projects/codetriage/public/assets/application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css"
2015-11-30 12:14:35 -0600

I can manually set the mtime of the gzipped file:

gz = Zlib::GzipWriter.new(f, Zlib::BEST_COMPRESSION)
puts target.inspect
gz.mtime = mtime
gz.write(@source)
gz.close

File.utime(mtime, mtime, f.path)

Then I get the right output:

$ ls -la public/assets/ | grep css
-rw-r--r--   1 richardschneeman  staff    24521 Nov 30 12:14 application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css
-rw-r--r--   1 richardschneeman  staff     5018 Nov 30 12:14 application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css.gz

and

$ rm public/assets/application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css
$ gzip -d public/assets/application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css.gz
$ ls -la public/assets/ | grep css
-rw-r--r--   1 richardschneeman  staff    24521 Nov 30 12:14 application-4b2d42bd6b734668146fd1f2650d9e33d7d62e4e69916a668f1de6061c2c176a.css

So either the Zlib::GzipWriter#mtime= doesn't work or it is doing something different than what we want/expect. If we want the mtimes to match (and I think we do) manually setting that value is the way to go. However sprockets was doing the "wrong" thing for years with gzip assets and no one ever noticed and it didn't seem to have any adverse effects. The extra mtime change, does require a file operation, it doesn't seem to add that much overhead, but it isn't free. I'm thinking we stick with the technically correct solution. I'll open an issue in Ruby stdlib and see if there is a bug in mtime= or if the docs need to be updated.

@schneems
Copy link
Member Author

schneems commented Dec 4, 2015

I looked on http://www.zlib.net/ and none of the specifications mention using the mtime header in the gzip file for anything. It looks like it is purely for informational purposes. I want to update the Ruby docs to indicate that it isn't doing what you likely think it is doing. I messaged the zlib list to see if that is a correct and valid thing to add to the Ruby docs. I'll send a patch when I hear back.

This change pulls mtime from stat instead of relying on the asset object. Reference: 16ccffc#commitcomment-14779288

We don't need to use the environment stat cache because this file has likely never been stat-ed before.

We also need to explicitly set the mtime of the file since it appears setting the mtime header has no impact on the mtime of the decompressed file.
In the case where a deploy was happening after all the assets were already generated, a future to write a file to disk is not created, (i.e. in the "skipped writing" file code path). We now check for the presence of this future before trying to `wait!` on it.
schneems added a commit that referenced this pull request Dec 5, 2015
Asset#mtime was deprecated and not the correct value
@schneems schneems merged commit 8aa7455 into 3.x Dec 5, 2015
@arthurnn arthurnn deleted the schneems/fix-mtime3 branch December 5, 2015 21:10
schneems added a commit that referenced this pull request Dec 6, 2015
See #197 (comment) for more information.
schneems added a commit that referenced this pull request Dec 6, 2015
See #197 (comment) for more information.
@schneems
Copy link
Member Author

schneems commented Dec 8, 2015

I got a response from the zlib group.

> Are there any deflate implementations that use the mtime header for a specific 
purpose that you know about?

Again, this is about gzip, not deflate. gzip itself uses the MTIME field to restore the 
modification time of the file, if requested. So a gunzip -N foo.gz will restore foo 
with the modification time of January 2001.

So the header is used in some cases as anticipated but it might not be the default behavior. I think the correct thing to do based on this information and the nginx docs is to set the mtime of the file and the header to the same value which matches the original file. This is what we are currently doing.

@fxn
Copy link
Member

fxn commented Dec 8, 2015

Awesome!

schneems added a commit to schneems/ruby that referenced this pull request Dec 8, 2015
This was discussed in rails/sprockets#197. The behavior and results of setting mtime via this method were unclear. This document should help clarify the behavior.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants