Packit-service: SRPM build failed: ls: cannot access 'cockpit-*.tar.xz': No such file or directory

[sentry-io[bot]]

Sentry Issue: PACKIT-SERVICE-37H

SandcastleCommandFailed: Command failed (rc=2, reason={"metadata":{},"status":"Failure","message":"command terminated with non-zero exit code: Error executing in Docker Container: 2","reason":"NonZeroExitCode","details":{"causes":[{"reason":"ExitCode","message":"2"}]}})
ls: cannot access 'cockpit-*.tar.xz': No such file or directory

(1 additional frame(s) were not displayed)
...
  File "packit/upstream.py", line 693, in prepare_upstream_for_srpm_creation
    created_archive = self.create_archive(version=current_git_describe_version)
  File "packit/upstream.py", line 317, in create_archive
    outputs = self.get_output_from_action(
  File "packit/base_git.py", line 302, in get_output_from_action
    self.command_handler.run_command(
  File "packit/command_handler.py", line 162, in run_command
    out: str = self.sandcastle.exec(command=command, env=env, cwd=cwd)
  File "sandcastle/api.py", line 626, in exec
    raise SandcastleCommandFailed(output=response, reason=errors, rc=rc)

PackitSRPMException: Preparing of the upstream to the SRPM build failed: Command failed (rc=2, reason={"metadata":{},"status":"Failure","message":"command terminated with non-zero exit code: Error executing in Docker Container: 2","reason":"NonZeroExitCode","details":{"causes":[{"reason":"ExitCode","message":"2"}]}})
ls: cannot access 'cockpit-*.tar.xz': No such file or directory

  File "packit_service/worker/build/build_helper.py", line 355, in _create_srpm
    self.api.create_srpm(srpm_dir=self.api.up.local_project.working_dir)
  File "packit/api.py", line 522, in create_srpm
    raise PackitSRPMException(

[sentry-io[bot]]

Sentry issue: PACKIT-SERVICE-37J

[jpopelka]

There was also one occurrence of PACKIT-SERVICE-2YC (create-archive action did not output a path to generated archive) which looks related.

[martinpitt]

This is likely from https://github.com/martinpitt/cockpit/pull/12 , from this weird log. That says:

11:05:10.248 command_handler.py INFO   Running command: env GITHUB_BASE=martinpitt/cockpit test/make_dist.py --wait

Message: Preparing of the upstream to the SRPM build failed: ['oc', 'rsync', '--delete', '--quiet=true', '--namespace=packit-prod-sandbox', 'docker-io-usercont-sandcastle-prod-20210309-110447505409:/sandcastle/docker-io-usercont-sandcastle-prod-20210309-110447505409/', '/sandcastle'] failed with 'WARNING: cannot use rsync: rsync not available in container\nWARNING: cannot use tar: tar not available in container\nerror: No available strategies to copy.\n'
Exception: PackitSRPMException("Preparing of the upstream to the SRPM build failed: ['oc', 'rsync', '--delete', '--quiet=true', '--namespace=packit-prod-sandbox', 'docker-io-usercont-sandcastle-prod-20210309-110447505409:/sandcastle/docker-io-usercont-sandcastle-prod-20210309-110447505409/', '/sandcastle'] failed with 'WARNING: cannot use rsync: rsync not available in container\\nWARNING: cannot use tar: tar not available in container\\nerror: No available strategies to copy.\\n'")
You can retrigger the build by adding a comment (`/packit build`) into this pull request

... which is not particularly helpful. Earlier runs this morning (where I had only a PoC hack to get the tarball) worked fine. Now the create-archive: command mostly sits around waiting/polling for the tarball to appear, which takes about 10 minutes. Could this be a timeout, with a really odd error message?

[jpopelka]

I don't see much more in worker logs: http://pastebin.test.redhat.com/945717

[martinpitt]

I did a packit rebuild in that PR, which did get a bit further:

11:57:17.729 command_handler.py INFO   Output of ['env', 'GITHUB_BASE=martinpitt/cockpit', 'test/make_dist.py', '--wait']:
11:57:17.730 command_handler.py INFO   make_dist: Downloading dist tarball from https://github.com/martinpitt/cockpit-dist/raw/master/39816bb67587baeec45bd48001d53235be0f304f.tar ...
11:57:17.730 command_handler.py INFO   make_dist: Extracting directories from tarball: dist node_modules
11:57:17.730 command_handler.py INFO   /sandcastle/docker-io-usercont-sandcastle-prod-20210309-115642582168/cockpit-239.37.g39816bb67.tar.xz

Message: Preparing of the upstream to the SRPM build failed: The create-archive action did not output a path to the generated archive. Please make sure that you have valid path in the single line of the output.

I suppose that output is now not strictly a single line, but I thought it would only look at the last line? Local packit srpm works fine.

[martinpitt]

@jpopelka : Oh, I think that ls cockpit-*.tar.xz was from some intermediate run, that one was definitively broken. The current packit file does not use that. Although I will try this again to test for the theory that it really only accepts a single line of output.

But I guess there is still some timeout issue somewhere, due to the first log when it didn't even get that far.

[martinpitt]

I did a new run with an extra hack that enforces a single line print. It still fails exactly like before. That was again the "initial push case where create-archive takes about 10 minutes. I will now restart it again, this time the tarball exists already and download is fast.

Update: The retry worked. So this proves two things:

• Unlike with local packit srpm, the service insists on a single line of output for the tarball, it does not just look at the last line of output.
• Having a create-archive: command which takes more than 30 s seems to be broken.

[martinpitt]

So, my shabby workaround for that would be for the workflow that generates the downloadable tarball to sent an automatic /packit build comment to the PR to restart the failed srpm build. :grin: With doing that manually, it succeeded :tada:

[martinpitt]

So AFAICS there are two paths here:

• Allow create-archive to take a longer time (possibly configurable timeout?)
• Allow PRs to trigger packit runs manually (i.e. through workflow automation), instead of immediately starting on the pull_request webhook -- we know that we need to wait for the tarball, so starting packit when ready instead of adding this waiting loop would be more elegant, and also avoid needlessly keeping a sandcastle container being idle in a polling loop for 10 minutes.

Now, we already have the "trigger manually", we would only somehow need to tell packit to not trigger tests on pull_requests. Right now it does:

  - job: tests
    trigger: pull_request
    metadata:
      targets:
      # once this works, move to fedora-all
      - fedora-33

At the moment the documentation only supports that single trigger for tests (we don't want to use push or release) either; would it be reasonable to have trigger: comment or trigger: manual or something such? or a webhook-like URL that we could call to start them?

[TomasTomecek]

Ad 1: I was thinking if it was acceptable for you to poll for archive to land in the target location - in the create-archive action. Certainly not the best, but should do the trick.

Ad 2: I actually really like the webhook part :) or even comment/manual trigger.

Auth would be the biggest problem for the webhook part - not sure if we could verify that the request is coming from the Github action of the same project.

[martinpitt]

@TomasTomecek : For 1, that's what it does now, with the polling. But when it does that, something goes wrong (timeout? some bug in our make_dist.py --wait script?) and causes the above weird log (about missing tar/rsync), so it's hard for me to figure out what it is.

2) Good point about validating the origin. I suppose it's easiest to just use the existing /packit build commands -- it's really easy to generate a commit from a workflow, both from "number of lines of code" (some 5?) and from the authentication structure (a workflow in a project has a default token that can send comments).

How much effort you spend on the "don't trigger automatically" part depends (I suppose) how painful/expensive it is to you to have these idle polling sandcastle containers for 10 or 15 mins for every PR.

[martinpitt]

On second sight this may not actually be a too short timeout. I was watching the yellow/red dots in https://github.com/martinpitt/cockpit/pull/12 pretty closely now, and the packit "building srpm..." task did stay around for the entire polling time, until the upstream tarball got built. Only then it failed with the usual "no rsync or tar wahwah" error. So I'm afraid I'll need a more useful log to know what's going on..

[martinpitt]

Hmm, now I got the same error on a /packit rebuild run where the tarball should be immediately available.

Update: I think that was wrong -- the workflow missed to build a dist archive for that case, so it probably just timed out.

[martinpitt]

@TomasTomecek just looked at that (thanks!) and found out that this is due to the pod having a timeout of 10 minutes. That explains why it sometimes works -- I've seen dist builds finish in 8 minutes, but mostly they take 11 or even 15 if GitHub is busy. Tomas dug out the real error message which shows that the pod just gets killed (137 == signal + SIGKILL), and then the oc rsync message is just confusing (it does not recognize that the pod is dead).

[TomasTomecek]

We have the fix deployed in stg now and the timeout was increased to 30 minutes. Both changes should be rolled out to prod on Monday.