Can't create new live log on branch

[Thegaram]

Can't create new live log on branch

[talex5]

That usually means that the function for calculating the branch name is missing some component of the key. i.e. you asked to build two different things, but storing the result with the same branch name.

Does the main page of the UI show something else building to that branch?

[Thegaram]

Well, my build is 1. build two docker containers, 2. run one of them. The container-building part works well and I can rebuild it. The error I mentioned comes from the second part (Docker.run).

Where is the "function for calculating the branch name" defined?

[talex5]

Should be something like:

datakit/ci/src/cI_docker.ml

Line 183 in 74494b3

let branch t {Key.image} =

Another possibility is that you're creating multiple in-memory caches. Check you're not calling Docker.create more than once with the same label.

[Thegaram]

No, I did not call Docker.create more than once with the same label.

My code is based on self-ci where I did not see an explicit definition of branch names.

[
  "runtests",  images#tests >>= fun img ->
               (Docker.run (Docker.command ~logs ~pool ~timeout:(30. *. minute) ~label:"test_label" ~network:"host" []) img)
               >|= fun () -> "Run succeeded"
]

I don't have to generate a new label everytime I use Docker.run do I?

[talex5]

No, test_label appears in the branch name, so that's not the problem.

It's been a while since I looked at this code, but maybe this is helpful:

The error is presumably coming from https://github.com/moby/datakit/blob/master/ci/src/cI_cache.ml#L204, which only gets called if branch_name isn't in the cache, checked at:

https://github.com/moby/datakit/blob/master/ci/src/cI_cache.ml#L273

That suggests that the branch name isn't in the cache, but a live log with that name exists.

Either it was never there (suggesting there are two instances of the cache), or it got removed by https://github.com/moby/datakit/blob/master/ci/src/cI_cache.ml#L140. But that won't remove pending builds, and only pending builds have logs.

That's because it only sets it to a non-pending value after removing the live log (https://github.com/moby/datakit/blob/master/ci/src/cI_cache.ml#L211), or after loading a saved result (but that never creates a live log in the first place).

[Thegaram]

Thanks for the links @talex5!

I've tried different combinations and this problem only seems to appear when I use Docker.run, not with Docker.build. (I could not try to run a single Docker.run though, cause it needs the image created by Docker.build.)

But I noticed some strange logs. When starting the ci:

ci_1  | 2018-03-22 15:58.57 INF [datakit-ci] Loaded cached result from git-pull-of-ee0f36f73dda4f3df4e18fdead0ba39ed2b1c05f
ci_1  | 2018-03-22 15:58.57 INF [datakit-ci] Loaded cached result from docker-build-Dockerfile.cucumber-of-ee0f36f73dda4f3df4e18fdead0ba39ed2b1c05f
ci_1  | 2018-03-22 15:58.57 INF [datakit-ci] Loaded cached result from docker-run-test_label-in-sha256-506f4a834ed365e58787feb88e0c5ef60e75c5975aae441e775cbba1cafcc88d
ci_1  | 2018-03-22 15:58.57 INF [datakit-ci] Record: status-myproject-ref-heads-master: runtests -> Run succeeded
ci_1  | 2018-03-22 15:58.57 INF [datakit-ci] Flush: Set myproject/ref/heads/master:runtests to Run succeeded
ci_1  | 2018-03-22 15:58.57 INF [datakit-ci] Loaded cached result from docker-run-test_label-in-sha256-506f4a834ed365e58787feb88e0c5ef60e75c5975aae441e775cbba1cafcc88d

This suggests that the branch names are in the cache. Notice, however, that there are two Loaded cached result from docker-run-test_label... entries.

Could those two identical entries somehow explain the problem? Or is it normal behavior?

For the record, here are the logs for rebuilding:

ci_1  | 2018-03-22 16:00.37 INF [datakit-ci] Running "docker" "run" "--rm" "--network" "host" "sha256:506f4a834ed365e58787feb88e0c5ef60e75c5975aae441e775cbba1cafcc88d"
ci_1  | 2018-03-22 16:00.37 INF [datakit-ci] Record: status-myproject-ref-heads-master: runtests -> Docker run test_label
ci_1  | 2018-03-22 16:00.37 INF [datakit-ci] Flush: Set myproject/ref/heads/master:runtests to Docker run test_label
ci_1  | 2018-03-22 16:00.38 INF [datakit-ci] Record: status-myproject-ref-heads-master: runtests -> Can't create new live log on branch "docker-run-test_label-in-sha256-506f4a834ed365e58787feb88e0c5ef60e75c5975aae441e775cbba1cafcc88d"; one is already active!
ci_1  | === Docker run test_label
ci_1  | [2018-03-22 16:00.37] Starting...
ci_1  | [2018-03-22 16:00.37] Running "docker" "run" "--rm" "--network" "host" "sha256:506f4a834ed365e58787feb88e0c5ef60e75c5975aae441e775cbba1cafcc88d"
ci_1  | 
ci_1  | 2018-03-22 16:00.38 INF [datakit-ci] Flush: Set myproject/ref/heads/master:runtests to Can't create new live log on branch "docker-run-test_label-in-sha256-506f4a834ed365e58787feb88e0c5ef60e75c5975aae441e775cbba1cafcc88d"; one is already active!
ci_1  | === Docker run test_label
ci_1  | [2018-03-22 16:00.37] Starting...
ci_1  | [2018-03-22 16:00.37] Running "docker" "run" "--rm" "--network" "host" "sha256:506f4a834ed365e58787feb88e0c5ef60e75c5975aae441e775cbba1cafcc88d"

[talex5]

It certainly looks like you've got two instances of the cache. I can't think of any other reason why it would load the same result twice.

Also, the Can't create new live log would cause the cache getting that to abort the operation, but the next line Docker run test_label suggests that it did indeed create the log (and is now logging to it). I don't see how that could happen with a single cache instance.

[talex5]

Where do you call Docker.create? Is it nested inside a function, perhaps?

[Thegaram]

For now, my code has exactly the same structure as self-ci:

module Dockerfile = struct
  (* [v ~timeout file] is a caching builder for [file]. *)
  let v ?label ~timeout file =
    let label = label |> Utils.default file in
    Docker.create ~logs ~pool ~timeout ~label file

  let test = v ~timeout:(30. *. minute) "Dockerfile.test"
end

module Tests = struct
  open Term.Infix

  let images src =
    let build ?from dockerfile =
      match from with
      | None -> src >>= Docker.build dockerfile ?from:None
      | Some from ->
        Term.without_logs (Term.pair src from) >>= fun (src, from) ->
        Docker.build dockerfile ~from src
    in
    object(_self)
      method test = build Dockerfile.test
    end

  (* [datakit repo target] is the set of tests to run on [target]. *)
  let datakit repo = function
    | `Ref (_, ["heads"; "gh-pages"]) -> []
    | target ->
      let src = Git.fetch_head repo target in
      let images = images src in
      [
        "runtests",  images#test >>= fun img ->
                     (Docker.run (Docker.command ~logs ~pool ~timeout:(30. *. minute) ~label:"test_label" ~network:"host" []) img)
                     >|= fun () -> "Run succeeded"
      ]
end

It seems to me that Docker.create, Docker.build, and Docker.run are all called exactly once. Any ideas?

[talex5]

Docker.command is being called at least every time a new image is produced, and it creates a new cache. You should create that once, at the top level.

[Thegaram]

Yep, that solves it, thanks @talex5! I didn't realize Docker.command also creates a new cache.

In case anyone struggles with the same issues, here's an example building and running one docker container:

module Tests = struct
  open Term.Infix

  let my_tests target =
    let timeout = (30. *. minute) in

    let repo = Git.v ~logs ~remote:"/mnt/my_project_remote" "/data/repos/my_project" in
    let src = Git.fetch_head repo target in
    let dockerfile = Docker.create ~logs ~pool ~timeout ~label:"tests" "Dockerfile" in
    let image = src >>= Docker.build ?from:None dockerfile in
    let command = Docker.command ~logs ~pool ~timeout ~label:"run" ~network:"host" [] in

    [
      "my_tests", image
                  >>= fun img -> (Docker.run command img)
                  >|= fun () -> "Run succeeded";
    ]
end

let projects = [
  Config.project ~id:"my/myproject" Tests.my_tests
]

[talex5]

I'm not sure that's right either. It will create (at least) a new cache for each target, which isn't what you want.

[Thegaram]

Okay, this seems to work:

module Repo = struct
  let my_project = Git.v ~logs ~remote:"/mnt/my_project_remote" "/data/repos/my_project"
end

module Dockerfile = struct
  let v ?label ~timeout file =
    let label = label |> Utils.default file in
    Docker.create ~logs ~pool ~timeout ~label file

  let main  = v ~label:"main"  ~timeout:(30. *. minute) "Dockerfile"
  let tests = v ~label:"tests" ~timeout:(30. *. minute) "Dockerfile.tests"
end

module Command = struct
  let tests = Docker.command ~logs ~pool ~timeout:(30. *. minute) ~label:"tests_run" ~network:"host" []
end

module Tests = struct
  open Term.Infix

  let images src =
    let build dockerfile = src >>= Docker.build dockerfile ?from:None in
    object(_self)
      method main  = build Dockerfile.main
      method tests = build Dockerfile.tests
    end

  let check_build term =
    term >|= fun _ -> "Build succeeded"

  let check_run term =
    term >|= fun _ -> "Run succeeded"

  let my_tests target =
    let src = Git.fetch_head Repo.my_project target in
    let images = images src in
    [
      "build_container",     check_build images#main;
      "build_and_run_tests", check_run (images#tests >>= Docker.run Command.tests);
    ]

end

let projects = [
  Config.project ~id:"me/my_project" (Tests.my_tests)
]