`.building` folder not getting renamed after a bulk build, something to do with `PKG_REPO_SIGNING_KEY` setting

seanm commented 2 years ago

Prerequisites

[x] Have you checked for an existing issue describing your problem?
[x] Are you running the latest version?
[x] Is your ports tree recent?
[x] Is your FreeBSD Host on a supported release?

Describe the bug

After poudriere bulk finishes, /usr/local/poudriere/data/packages/amd64-13-0-default/.building does not get renamed to the expected .real_<timestamp>, and no error messages are emitted. It has something to do with the PKG_REPO_SIGNING_KEY setting.

How to reproduce

Steps to reproduce the behavior:

Run poudriere bulk as typical, all packages build, no errors are emitted.
Look in /usr/local/poudriere/data/packages/amd64-13-0-default/ folder, note what's there and not.

Expected behavior

I expect the .building folder to no longer be present, but it is. I discovered that if I comment out my PKG_REPO_SIGNING_KEY setting, then all is well. and/or I expect some error message to be emitted.

Hopefully you can repro by setting PKG_REPO_SIGNING_KEY to something bad, like pointing it to a random file. I suspect there's some missing error checking when/if signing fails.

I'm not actually sure yet what it doesn't like about my own privkey.pem. The path is correct. I tried chmod 777 but that didn't help either.

Environment

FreeBSD 13.0-RELEASE-p6
Poudriere Version 3.3.7_1

grahamperrin commented 2 years ago

FreeBSD 13.0-RELEASE-p6

Any reason to not update?

seanm commented 2 years ago

Any reason to not update?

Hmmm, didn't even know there was a p7! I'll update, but do you actually think it will affect this ticket?

bdrewery commented 2 years ago

No that wouldn't matter.

I tried this with 3.3.7 without any problem. Can you provide a bulk log and your poudriere.conf files please?

seanm commented 2 years ago

I have a new guess as to what the root problem may be...

In poudriere.conf, it says:

# Path to the RSA key to sign the PKG repo with. See pkg-repo(8)
PKG_REPO_SIGNING_KEY=/usr/local/etc/acme.sh/privkey.pem

Does it literally have to be an RSA key, as opposed to an ECDSA key?

Around the same time my poudriere became broken, I also updated my Let's Encrypt cert, and I switched from RSA to ECDSA. file identifies it as such:

# file /usr/local/etc/acme.sh/privkey.pem 
/usr/local/etc/acme.sh/privkey.pem: PEM EC private key

Could that be the issue? I can renew/replace the cert early and go back to RSA as a test...

bdrewery commented 2 years ago

How did you generate the key?

seanm commented 2 years ago

With acme.sh. Specifically:

acme.sh --server letsencrypt --issue --dns -d foo.example.com -d pkg.example.com --keylength ec-256 --yes-I-know-dns-manual-mode-enough-go-ahead-please

bdrewery commented 2 years ago

Not sure if that one works, but in any case I don't see any way that failure would cause .building to be present and not have an exit error. I can only reproduce errors. So I would need more information to understand this.

The EVP_DigestVerifyInit interface is used to sign and verify the signature https://www.openssl.org[/docs/manmaster/man1/openssl-dgst.html has more details.

seanm commented 2 years ago

Here is my poudriere.conf.txt. I only anonymized URL_BASE .

seanm commented 2 years ago

I have updated to 13.0-RELEASE-p7.

I've uncommented my PKG_REPO_SIGNING_KEY to reproduce the issue.

Here's a directory listing before:

root@foo:/usr/local/poudriere/data/packages/amd64-13-0-default # ll
total 14
lrwxr-xr-x  1 root  wheel  18 Apr 15  2021 .buildname@ -> .latest/.buildname
lrwxr-xr-x  1 root  wheel  20 Apr 15  2021 .jailversion@ -> .latest/.jailversion
lrwxr-xr-x  1 root  wheel  16 Mar  9 01:14 .latest@ -> .real_1646806488
drwxr-xr-x  4 root  wheel  11 Mar  9 01:14 .real_1646806488/
lrwxr-xr-x  1 root  wheel  11 Apr 15  2021 All@ -> .latest/All
lrwxr-xr-x  1 root  wheel  14 Apr 15  2021 Latest@ -> .latest/Latest
lrwxr-xr-x  1 root  wheel  17 Apr 15  2021 meta.conf@ -> .latest/meta.conf
lrwxr-xr-x  1 root  wheel  16 Jul 23  2021 meta.pkg@ -> .latest/meta.pkg
lrwxr-xr-x  1 root  wheel  16 Apr 15  2021 meta.txz@ -> .latest/meta.txz
lrwxr-xr-x  1 root  wheel  23 Jul 23  2021 packagesite.pkg@ -> .latest/packagesite.pkg
lrwxr-xr-x  1 root  wheel  23 Apr 15  2021 packagesite.txz@ -> .latest/packagesite.txz

Notice there is no .building folder.

Then I build a single port with poudriere bulk -j amd64-13-0 databases/php81-dba:

[00:00:00] Creating the reference jail... done
[00:00:00] Mounting system devices for amd64-13-0-default
[00:00:00] Mounting ports/packages/distfiles
[00:00:00] Stashing existing package repository
[00:00:00] Mounting packages from: /usr/local/poudriere/data/packages/amd64-13-0-default
[00:00:00] Copying /var/db/ports from: /usr/local/etc/poudriere.d/amd64-13-0-options
[00:00:00] Appending to make.conf: /usr/local/etc/poudriere.d/make.conf
/etc/resolv.conf -> /usr/local/poudriere/data/.m/amd64-13-0-default/ref/etc/resolv.conf
[00:00:00] Starting jail amd64-13-0-default
[00:00:00] Will build as nobody: (65534:65534)
[00:00:01] Logs: /usr/local/poudriere/data/logs/bulk/amd64-13-0-default/2022-03-09_18h21m53s
[00:00:01] WWW: https://foo.example.com//build.html?mastername=amd64-13-0-default&build=2022-03-09_18h21m53s
[00:00:01] Loading MOVED for /usr/local/poudriere/data/.m/amd64-13-0-default/ref/usr/ports
[00:00:02] Ports supports: FLAVORS SELECTED_OPTIONS
[00:00:02] Gathering ports metadata
[00:00:03] Calculating ports order and dependencies
[00:00:04] Sanity checking the repository
[00:00:04] Checking packages for incremental rebuild needs
[00:00:04] Deleting stale symlinks... done
[00:00:04] Deleting empty directories... done
[00:00:04] Cleaning the build queue
[00:00:04] Sanity checking build queue
[00:00:04] Processing PRIORITY_BOOST
[00:00:04] Balancing pool
[00:00:04] Recording filesystem state for prepkg... done
[00:00:04] Building 1 packages using 1 builders
[00:00:04] Starting/Cloning builders
[00:00:05] Hit CTRL+t at any time to see build progress and stats
[00:00:05] [01] [00:00:00] Building databases/php81-dba | php81-dba-8.1.3
[00:00:22] [01] [00:00:17] Finished databases/php81-dba | php81-dba-8.1.3: Success
[00:00:22] Stopping 1 builders
[00:00:22] Creating pkg repository
Creating repository in /tmp/packages: 100%
Packing files for repository: 100%
[00:00:24] Cleaning up
[00:00:24] Unmounting file systems

That all looks normal to me (but I'm no expert). Then I list the directory again:

root@foo:/usr/local/poudriere/data/packages/amd64-13-0-default # ll
total 22
drwxr-xr-x  4 root  wheel  11 Mar  9 18:22 .building/
lrwxr-xr-x  1 root  wheel  18 Apr 15  2021 .buildname@ -> .latest/.buildname
lrwxr-xr-x  1 root  wheel  20 Apr 15  2021 .jailversion@ -> .latest/.jailversion
lrwxr-xr-x  1 root  wheel  16 Mar  9 01:14 .latest@ -> .real_1646806488
drwxr-xr-x  4 root  wheel  11 Mar  9 01:14 .real_1646806488/
lrwxr-xr-x  1 root  wheel  11 Apr 15  2021 All@ -> .latest/All
lrwxr-xr-x  1 root  wheel  14 Apr 15  2021 Latest@ -> .latest/Latest
lrwxr-xr-x  1 root  wheel  17 Apr 15  2021 meta.conf@ -> .latest/meta.conf
lrwxr-xr-x  1 root  wheel  16 Jul 23  2021 meta.pkg@ -> .latest/meta.pkg
lrwxr-xr-x  1 root  wheel  16 Apr 15  2021 meta.txz@ -> .latest/meta.txz
lrwxr-xr-x  1 root  wheel  23 Jul 23  2021 packagesite.pkg@ -> .latest/packagesite.pkg
lrwxr-xr-x  1 root  wheel  23 Apr 15  2021 packagesite.txz@ -> .latest/packagesite.txz

Notice the .building folder is still there, and the .real timestamp is not newer.

bdrewery commented 2 years ago

Creating repository in /tmp/packages: 100%
Packing files for repository: 100%
[00:00:24] Cleaning up
[00:00:24] Unmounting file systems

That's most likely an error. Try echo $? after it exits.

It should look something like this and indicate what was built and how long it took, where logs are, etc. Sorry the error state isn't clear there. I think I see why that happens at least.

Packing files for repository: 100%
[00:00:39] Committing packages to repository: /poudriere/data/packages/exp-12amd64-33-commit-test/.real_1646864698 via .latest symlink
[00:00:39] Removing old packages
[00:00:39] Built ports: ports-mgmt/poudriere
[exp-12amd64-33-commit-test] [2022-03-09_14h24m19s] [committing:] Queued: 1  Built: 1  Failed: 0  Skipped: 0  Ignored: 0  Tobuild: 0   Time: 00:00:33
[00:00:39] Logs: /poudriere/data/logs/bulk/exp-12amd64-33-commit-test/2022-03-09_14h24m19s
[00:00:39] WWW: http://.../build.html?mastername=exp-12amd64-33-commit-test&build=2022-03-09_14h24m19s
[00:00:39] Cleaning up
[00:00:39] Unmounting file systems

I have this change that I'll commit soon to make the error more obvious. Needs more local testing still.

[00:00:15] Creating pkg repository
Creating repository in /tmp/packages: 100%
Packing files for repository: 100%
[ERROR] Unhandled error! Exiting 1
[00:00:17] Cleaning up
[00:00:17] Unmounting file systems

seanm commented 2 years ago

Try echo $? after it exits.

It returns 1.

[ERROR] Unhandled error! Exiting 1

Seeing something like that would be extremely helpful! It would fix half my problem. There remains the fact that commenting out PKG_REPO_SIGNING_KEY makes things work.

bdrewery commented 2 years ago

I will also add some indicator that a key is even being used, or that pkg repo failed!

bdrewery commented 2 years ago

[00:00:15] Stopping 1 builders
[00:00:15] Creating pkg repository
[00:00:17] Signing repository with key: /usr/local/etc/poudriere.d/pkgng.pem
Creating repository in /tmp/packages: 100%
Packing files for repository: 100%
[00:00:17] Error: Failed to sign pkg repository
[00:00:17] Cleaning up
[00:00:17] Unmounting file systems
Exiting with status 1

seanm commented 2 years ago

Nice!

So shall I try going back to an RSA key, or is there some other way to debug what's failing for me?

seanm commented 2 years ago

I've confirmed the issue is RSA key vs ECC key. Changing only that makes the issue occur or not.

seanm commented 2 years ago

I've just updated to 13.1-RELEASE; any point in me retesting this?

bdrewery commented 2 years ago

@seanm I don't think so

freebsd / poudriere