Failed to open statefile: could not set effective uid

[fhgwright (Fred Wright)]

Today's port upgrade outdated ran afoul of the following:

12:23:28.019:: Error: Failed to open statefile for py27-gnureadline: could not set effective uid to 503: 1 Operation not permitted
12:23:28.750:: Error: Failed to open statefile for py27-libxml2: could not set effective uid to 503: 1 Operation not permitted
12:23:34.123:: Error: Failed to open statefile for py37-zipp: could not set effective uid to 503: 1 Operation not permitted
12:23:35.636:: Error: Failed to open statefile for py37-iniconfig: could not set effective uid to 503: 1 Operation not permitted
12:23:38.303:: Error: Failed to open statefile for py39-astroid: could not set effective uid to 503: 1 Operation not permitted
12:23:38.411:: Error: Failed to open statefile for py39-distlib: could not set effective uid to 503: 1 Operation not permitted
12:23:40.162:: Error: Failed to open statefile for py39-setuptools: could not set effective uid to 503: 1 Operation not permitted
12:23:42.164:: Error: Failed to open statefile for py39-virtualenv: could not set effective uid to 503: 1 Operation not permitted
12:23:44.548:: Error: Failed to open statefile for py310-astroid: could not set effective uid to 503: 1 Operation not permitted
12:23:45.122:: Error: Failed to open statefile for py310-distlib: could not set effective uid to 503: 1 Operation not permitted
12:23:46.842:: Error: Failed to open statefile for py310-setuptools: could not set effective uid to 503: 1 Operation not permitted
12:23:48.472:: Error: Failed to open statefile for py310-virtualenv: could not set effective uid to 503: 1 Operation not permitted
12:23:50.342:: Error: Failed to open statefile for py311-astroid: could not set effective uid to 503: 1 Operation not permitted
12:23:50.427:: Error: Failed to open statefile for py311-setuptools: could not set effective uid to 503: 1 Operation not permitted
12:23:50.508:: Error: Failed to open statefile for py312-astroid: could not set effective uid to 503: 1 Operation not permitted
12:23:50.602:: Error: Failed to open statefile for py312-setuptools: could not set effective uid to 503: 1 Operation not permitted
12:23:50.684:: Error: Failed to open statefile for py313-astroid: could not set effective uid to 503: 1 Operation not permitted
12:23:53.410:: Error: Failed to open statefile for ruby32: could not set effective uid to 503: 1 Operation not permitted
12:23:54.367:: Error: Failed to open statefile for sshfs: could not set effective uid to 503: 1 Operation not permitted
12:23:56.594:: Error: Failed to open statefile for sudo: could not set effective uid to 503: 1 Operation not permitted

I've never seen this particular disease before, so it probably relates to the 2.11.3 update. It persists after cleaning the listed ports. This is on 10.9 (not yet attempted on other OS versions). It's not with the new sudo, since that was one of the ports that it failed to upgrade.

[fhgwright (Fred Wright)]

Now that I've run this on most other systems, I can elaborate. I see the same thing on 10.5 ppc and 10.5-10.15 x86 (all of them). The exact set of ports varies with the particular system.

Also, the base update failed on 12.x x86, though that's probably unrelated.

[jmroot (Joshua Root)]

I'm not able to reproduce this so far. Can you provide debug output? Does this only happen with upgrade?

[fhgwright (Fred Wright)]

I haven't had occasion to try it with anything other than upgrade.

I'll attach a debug log from the 10.15 case, which is the newest OS where I've seen it.

[fhgwright (Fred Wright)]

Debug output from statefile access failure on 10.15

[jmroot (Joshua Root)]

Thanks. Can you please apply [3d9bb762213c99bf4b33a5d76ccaf147b8100903/macports-base] to your portutil.tcl, which should hopefully add a backtrace showing exactly which call failed? Also could you check if running a single target on one of the affected ports has the same result, e.g. sudo port -d fetch py37-zipp?

[jmroot (Joshua Root)]

Actually, the error in the log is different to the one in the ticket description:

Failed to open statefile for py37-zipp: couldn't open "/opt/local/var/macports/build/py37-zipp-bd17e75d/work/.macports.py37-zipp.state": permission denied

vs

Error: Failed to open statefile for py27-gnureadline: could not set effective uid to 503: 1 Operation not permitted

I guess it's possible that they're related if the euid is not being changed correctly. What does ls -l /opt/local/var/macports/build/py37-zipp-bd17e75d/work/.macports.py37-zipp.state say?

[fhgwright (Fred Wright)]

Replying to jmroot:

Actually, the error in the log is different to the one in the ticket description:

Failed to open statefile for py37-zipp: couldn't open "/opt/local/var/macports/build/py37-zipp-bd17e75d/work/.macports.py37-zipp.state": permission denied

vs

Error: Failed to open statefile for py27-gnureadline: could not set effective uid to 503: 1 Operation not permitted

Ah, I didn't look closely enough to notice that. I just saw statefile access errors in many cases. The original description is from the 10.9 case, which would be a much bigger log.

I guess it's possible that they're related if the euid is not being changed correctly. What does ls -l /opt/local/var/macports/build/py37-zipp-bd17e75d/work/.macports.py37-zipp.state say?

That file didn't even exist, making "permission denied" a lie unless it was for the directory. Just doing a clean and a fetch succeeded, though the build failed in a different way on the upgrade, which is probably unrelated. The debug fragment for that is:

DEBUG: system:  cd "/opt/local/var/macports/build/py37-zipp-bd17e75d/work/zipp-3.15.0" && /opt/local/Library/Frameworks/Python.framework/Versions/3.7/bin/python3.7 -m build --no-isolation --wheel --outdir /opt/local/var/macports/build/py37-zipp-bd17e75d/work --skip-dependency-check 
* Building wheel...
usage: _in_process.py [global_opts] cmd1 [cmd1_opts] [cmd2 [cmd2_opts] ...]
   or: _in_process.py --help [cmd1 cmd2 ...]
   or: _in_process.py --help-commands
   or: _in_process.py cmd --help

error: invalid command 'bdist_wheel'

ERROR Backend subprocess exited when trying to invoke build_wheel

I hadn't tried cleaning in the non-10.9 cases, since it hadn't helped on 10.9.

Tripping over prior build-tree contents is still a bug, albeit a less serious one.

[fhgwright (Fred Wright)]

I tried the 10.9 cases again, and it looks like the bug only occurs with upgrade outdated (with -p due to the various build failures). Upgrading the ports by explicit name (including with all on one command line) doesn't run afoul of the problem.

[fhgwright (Fred Wright)]

In addition, after upgrading all the affected ports that could be upgraded, the ones that couldn't due to build failures no longer hit the statefile bug on upgrade outdated.

[fhgwright (Fred Wright)]

It came back again on 10.9. I'm attaching the debug log. It's ginormous due to all the broken ports.

[fhgwright (Fred Wright)]

Debug output from statefile access failure on 10.9

[jmroot (Joshua Root)]

Since this appears to be two separate issues, let's make this ticket about the effective uid error, and handle the failure to open the statefile in #72740.