Heroku CI requires to always rebuild

[fbjork]

I'm currently testing the Heroku CI beta and noticed that randomly tests would fail due to new code not being complied properly.

I can work around this by setting always_rebuild=true, but I would prefer not to. Any idea what's going on?

[ericmj]

In what way is the code not compiled correctly? Is it missing some files or skipping compilation completely for CI builds?

[ericmj]

/cc @joshwlewis

[fbjork]

It's missing some files that should have been compiled. Could be from force pushing to the branch?

[ericmj]

Force push should not affect it. What kind of files are missing, is it skipping compiling some files or are source files? Are you seeing any errors?

[fbjork]

Here's the test setup log:

-----> Fetching https://github.com/HashNuke/heroku-buildpack-elixir buildpack...
       buildpack downloaded
-----> Elixir app detected
       * MIX_ENV=test
-----> Checking Erlang and Elixir versions
       Will use the following versions:
       * Stack cedar-14
       * Erlang 19.0
       * Elixir 1.3.4 
       Will export the following config vars:
       * Config vars BUGSNAG_API_KEY DATABASE_URL MIX_ENV NEWRELIC_APP_NAME NEWRELIC_LICENSE_KEY
       * MIX_ENV=test
-----> Using cached Erlang 19.0
-----> Installing Erlang 19.0 
cp: cannot copy a directory, '/tmp/cache425910599/erlang', into itself, '/app/.platform_tools/erlang/erlang'
-----> Using cached Elixir v1.3.4
-----> Installing Elixir v1.3.4 
-----> Installing Hex
23:15:37.169 [error] Failed updating session: 
   ProfileName: :httpc_mix
   SessionId:   {{'repo.hex.pm', 443}, #PID<0.113.0>}
   Pos:         7
   Value:       0
when
   Session (db) info: :undefined
   Session (db):      {:session, {{'repo.hex.pm', 443}, #PID<0.113.0>}, false, :https,
 {:sslsocket, {:gen_tcp, #Port<0.4608>, :tls_connection, :undefined},
  #PID<0.114.0>}, {:essl, []}, 1, :keep_alive, true}
   Session (record):  {:EXIT,
 {:badarg,
  [{:ets, :lookup,
    [:httpc_mix__session_db, {{'repo.hex.pm', 443}, #PID<0.113.0>}], []},
   {:httpc_manager, :lookup_session, 2, [file: 'httpc_manager.erl', line: 189]},
   {:httpc_handler, :update_session, 4,
    [file: 'httpc_handler.erl', line: 1909]},
   {:httpc_handler, :handle_empty_queue, 4,
    [file: 'httpc_handler.erl', line: 1368]},
   {:httpc_handler, :handle_info, 2, [file: 'httpc_handler.erl', line: 471]},
   {:gen_server, :try_dispatch, 4, [file: 'gen_server.erl', line: 601]},
   {:gen_server, :handle_msg, 5, [file: 'gen_server.erl', line: 667]},
   {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]}}
   T: :error
   E: :badarg
23:15:37.171 [error] Failed updating session: 
   ProfileName: :httpc_mix
   SessionId:   {{'repo.hex.pm', 443}, #PID<0.113.0>}
   Pos:         9
   Value:       true
when
   Session (db) info: :undefined
   Session (db):      {:session, {{'repo.hex.pm', 443}, #PID<0.113.0>}, false, :https,
 {:sslsocket, {:gen_tcp, #Port<0.4608>, :tls_connection, :undefined},
  #PID<0.114.0>}, {:essl, []}, 1, :keep_alive, false}
   Session (record):  {:EXIT,
 {:badarg,
  [{:ets, :lookup,
    [:httpc_mix__session_db, {{'repo.hex.pm', 443}, #PID<0.113.0>}], []},
   {:httpc_manager, :lookup_session, 2, [file: 'httpc_manager.erl', line: 189]},
   {:httpc_handler, :update_session, 4,
    [file: 'httpc_handler.erl', line: 1909]},
   {:httpc_handler, :maybe_make_session_available, 2,
    [file: 'httpc_handler.erl', line: 1516]},
   {:httpc_handler, :answer_request, 3,
    [file: 'httpc_handler.erl', line: 1507]},
   {:httpc_handler, :terminate, 2, [file: 'httpc_handler.erl', line: 759]},
   {:gen_server, :try_terminate, 3, [file: 'gen_server.erl', line: 629]},
   {:gen_server, :terminate, 7, [file: 'gen_server.erl', line: 795]}]}}
   T: :error
   E: :badarg
23:15:37.240 [error] GenServer #PID<0.113.0> terminating
** (stop) {:failed_updating_session, [profile: :httpc_mix, session_id: {{'repo.hex.pm', 443}, #PID<0.113.0>}, pos: 9, value: true, etype: :error, error: :badarg, stacktrace: [{:ets, :update_element, [:httpc_mix__session_db, {{'repo.hex.pm', 443}, #PID<0.113.0>}, {9, true}], []}, {:httpc_manager, :update_session, 4, [file: 'httpc_manager.erl', line: 210]}, {:httpc_handler, :update_session, 4, [file: 'httpc_handler.erl', line: 1887]}, {:httpc_handler, :maybe_make_session_available, 2, [file: 'httpc_handler.erl', line: 1516]}, {:httpc_handler, :answer_request, 3, [file: 'httpc_handler.erl', line: 1507]}, {:httpc_handler, :terminate, 2, [file: 'httpc_handler.erl', line: 759]}, {:gen_server, :try_terminate, 3, [file: 'gen_server.erl', line: 629]}, {:gen_server, :terminate, 7, [file: 'gen_server.erl', line: 795]}]]}
    (inets) httpc_handler.erl:1911: :httpc_handler.update_session/4
    (inets) httpc_handler.erl:1516: :httpc_handler.maybe_make_session_available/2
    (inets) httpc_handler.erl:1507: :httpc_handler.answer_request/3
    (inets) httpc_handler.erl:759: :httpc_handler.terminate/2
    (stdlib) gen_server.erl:629: :gen_server.try_terminate/3
    (stdlib) gen_server.erl:795: :gen_server.terminate/7
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Last message: {:ssl, {:sslsocket, {:gen_tcp, #Port<0.4608>, :tls_connection, :undefined}, #PID<0.114.0>}, <<49, 203, 146, 108, 33, 44, 135, 250, 172, 124, 224, 9, 56, 87, 107, 211, 132, 159, 25, 66, 81, 210, 213, 44, 0, 104, 175, 124, 160, 220, 192, 202, 146, 180, 67, 22, 191, 132, 103, 105, 78, 144, 187, 199, 75, 115, 158, 199, ...>>}
State: {:state, {:request, #Reference<0.0.1.196>, #PID<0.71.0>, 0, :https, {'repo.hex.pm', 443}, '/installs/1.3.0/hex-0.14.1.ez', [], :get, {:http_request_h, :undefined, 'keep-alive', :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, 'repo.hex.pm', :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, [], 'Mix/1.3.4', :undefined, :undefined, :undefined, '0', :undefined, :undefined, :undefined, :undefined, :undefined, ...}, {[], []}, {:http_options, 'HTTP/1.1', :infinity, true, {:essl, []}, :undefined, true, :infinity, false}, 'https://repo.hex.pm/installs/1.3.0/hex-0.14.1.ez', [], :none, [], 1480979737048, :undefined, :undefined, false}, {:session, {{'repo.hex.pm', 443}, #PID<0.113.0>}, false, :https, {:sslsocket, {:gen_tcp, #Port<0.4608>, :tls_connection, :undefined}, #PID<0.114.0>}, {:essl, []}, 1, :keep_alive, false}, {'HTTP/1.1', 200, 'OK'}, {:http_response_h, 'public, max-age=604800', 'keep-alive', 'Mon, 05 Dec 2016 23:15:37 GMT', :undefined, :undefined, :undefined, :undefined, '1.1 varnish', :undefined, 'bytes', '341908', '"3578572a51b34376e1b195375e140b71"', :undefined, :undefined, :undefined, 'AmazonS3', :undefined, :undefined, :undefined, :undefined, :undefined, '455416', :undefined, :undefined, :undefined, 'application/andrew-inset', :undefined, 'Thu, 24 Nov 2016 16:34:18 GMT', [{'x-amz-id-2', 'RxRrG6cIcnzxygf7qj3jtArq4IegNSxCfHAnjmaGFHZMQA/yaffEWRdKUFaflzczQBPDTJP5K1s='}, {'x-amz-request-id', '3C59FE436D80606C'}, {'x-amz-replication-status', 'FAILED'}, {'x-amz-meta-surrogate-key', 'installs'}, {'x-amz-version-id', '3sHhQuYLS9kukkJvPakVeMotMkDIDJ1u'}, {'x-served-by', 'cache-iad2138-IAD'}, {'x-cache', 'HIT'}, {'x-cache-hits', '1'}, {'x-timer', 'S1480979737.054051,VS0,VE1'}]}, :undefined, {:httpc_response, :whole_body, [<<80, 75, 3, 4, 20, 0, 0, 0, 0, 0, 42, 140, 120, 73, 16, 181, 134, 225, 32, 108, 0, 0, 32, 108, 0, 0, 34, 0, 0, 0, 104, 101, 120, 45, 48, 46, 49, 52, 46, 49, ...>>, 455416]}, {[], []}, {[], []}, :new, [], :nolimit, :nolimit, {:options, {:undefined, []}, {:undefined, []}, 0, 2, 5, 120000, 2, :disabled, false, :inet, :default, :default, []}, {:timers, [], :undefined}, :httpc_mix, :inactive}
* creating /app/.mix/archives/hex-0.14.1
-----> Installing rebar
* creating /app/.mix/rebar
* creating /app/.mix/rebar3
-----> Fetching app dependencies with mix
Running dependency resolution
All dependencies up to date
cp: cannot stat ‘/app/.hex/registry.ets’: No such file or directory
-----> Copying hex from /app/.mix/archives/hex-0.14.1
cp: ‘/app/.mix/archives/hex-0.14.1’ and ‘/app/.mix/archives/hex-0.14.1’ are the same file
-----> Compiling
-----> Creating .profile.d with env vars
-----> Writing export for multi-buildpack support
-----> No test-setup command provided. Skipping.

And here's the test log:

-----> Running Elixir buildpack tests...
TAP version 13
** (CompileError) test/controllers/product_shoot_controller_test.exs:26: PhotographyService.RetouchingQueue.__struct__/1 is undefined, cannot expand struct PhotographyService.RetouchingQueue
    (stdlib) lists.erl:1354: :lists.mapfoldl/3
    (stdlib) lists.erl:1354: :lists.mapfoldl/3
    test/controllers/product_shoot_controller_test.exs:23: (module)
    (stdlib) erl_eval.erl:670: :erl_eval.do_apply/6
-----> Elixir buildpack tests failed with exit status 1```

[joshwlewis]

Hi @fbjork -- I suspect this is a caching issue of some kind. I have some suspicions as to why. I'll look into it.

[gudmundur]

I think I've found the issue. When we're extracting the test cache, we're not respecting the atime and mtime of each file entry. I'm assuming that the Elixir compiler uses mtime to determine whether a recompile is necessary. I've created an issue for this and I hope we'll get it addressed in the next few days. We'll update you here when we've deployed the fix.

[gudmundur]

I've just deployed a change to our test runner that respects the mtime of a file in the test cache. I'd be curious to know how the rebuild works though. If you're caching compiled files inside the test cache, they'll have correct timestamps now. However, the source archive we obtain from GitHub does not retain timestamps. This is due to git archive not tracking the file system timestamps, which is as far as I know what GitHub uses internally for generating source archives.

All that said, I'd be curious to see if the issue has improved now, and also how the rebuild works. If we can support incremental builds, that would be pretty slick.

[ericmj]

If you're caching compiled files inside the test cache, they'll have correct timestamps now.

We are caching build artifacts in the normal slug compilation cache, is this different from the test cache? AFAIK, no caching changes were made when CI support was added.

However, the source archive we obtain from GitHub does not retain timestamps.

I think the assumption was that git will only touch changed files and the changed files will have a newer mtime than those extracted from the cache. If you are always retrieving a full source archive without timestamps this will not work, I would be surprised if incremental compilation for the app ever worked if this was the case. We never recompile deps unless they change though because the comparison is not based on mtimes.

[ericmj]

I wonder if we should change back to always force compiling the app 58710ee.

[joshwlewis]

We are caching build artifacts in the normal slug compilation cache, is this different from the test cache?

The test cache is shared for all test runs. So the cache will have compiled files from the last test run in that pipeline, which could be a different branch or commit. The cache for production builds is separate cache, and should contain cached files from the last build of that app.

AFAIK, no caching changes were made when CI support was added.

Yeah, that's true. It should not work any different.

If you are always retrieving a full source archive without timestamps this will not work, I would be surprised if incremental compilation for the app ever worked if this was the case.

I have a suspicion that your team would know if incremental builds weren't working for production builds. Heroku CI uses a slightly different build process than production builds, it's possible that the mtimes are lost only for CI.

We never recompile deps unless they change though because the comparison is not based on mtimes.

Can you clarify that? Do you mean app files are compiled based on mtimes, but dependencies are compiled based on something else?

[joshwlewis]

If you are always retrieving a full source archive without timestamps this will not work, I would be surprised if incremental compilation for the app ever worked if this was the case.

Hmm, actually, I think this may be right. Since git doesn't track mtimes, any git based deploy (like git push heroku master or auto/manual deploy from GitHub branches) would have app code mtimes very close to the current time of the build, which would mean app code gets recompiled every time.

However, the build-api should support mtimes, so incremental builds may work in that case.

[fbjork]

Did something change on Heroku's side this morning? No builds are working now in CI.

  Checking package (https://repo.hex.pm/tarballs/cowboy-1.0.4.tar)
  Using locally cached package
** (Mix) Unpacking tarball failed: no such file or directory```

[ericmj]

My guess is that the $HEX_HOME/cache.ets file is cached but $HEX_HOME/tarballs/... is not cached.

This is probably a bug in Hex also, it should not try to use a locally cached package if it does not exist. I will add a check for that in Hex.

[ericmj]

A workaround until I push out a new Hex version and this is fixed on the Heroku side is to add always_rebuild=true to the buildpack config. With this option we don't use the cache.

[fbjork]

We actually have always_rebuild=true set already. Note that this log is from the test setup step

[joshwlewis]

Actually, I was able to reproduce this on my own Elixir project. I've rolled back a change we shipped this morning, and it seems good again, can you confirm/deny @fbjork?

[fbjork]

Yes, works now!

Would be great to not have to always rebuild all the time, will that be possible?

[gudmundur]

@fbjork It sure would be nice. I'm not sure it's something we'll ever be able to support given that git doesn't track timestamps. If the recompilation check would be based on the contents of the file, rather than metadata, it'd be a different story.

The change that I deployed before the weekend caused the issues you were seeing. The error was a Invalid arguments from os.Chtimes in our test runner. The way the code was structured cause the cache extraction to stop at that point, resulting in a partial cache. I've got a PR open to attempt to update the mtime, but just log the error, rather than resulting in a partial cache. Hopefully it'll shed some light on why it's failing.

[gudmundur]

OK! I deployed a change to better inspect what was going on, and it turns out that the timestamp I was using i.e. ChangeTime refers to when attributes on the file changed, not the contents. I realized I should've been using ModTime all along.

I've just deployed that change, so file modification times should be set correctly now. Hopefully that'll help with partial recompilations.

[dcuddeback]

Does 73df63b fix this issue?

[ericmj]

I think it was already fixed but we can close this now. Please let us know if you still have issues.

[dcuddeback]

@ericmj Sounds good. We'll update our projects to use always_rebuild=false and let you know if we have any more issues. Thank you.

[gudmundur]

It's a shame we can't get incremental building working. We could get around this by updating the file modification times based on state we keep in the test cache. It does require elbow grease and fingerprinting of files.

[v-kat]

@ericmj we're noticing rebuilds on every CI run now. Has there been any change that could have affected this?

[ericmj]

Sorry, I don't really maintain this project anymore and I have never developed or tested the buildpack on Heroku CI.