Rename failing during upgrade - flags problem?

[tdb]

I'm doing a bunch of updates using pkg 1.4.6 on FreeBSD 8.4-RELEASE-p19 i386. It's failing repeatedly (I fix one problem and another appears further on) with errors like this:

[51/143] Installing policykit-0.9_8...
[51/143] Extracting policykit-0.9_8:   7%===> Creating users and/or groups.
[51/143] Extracting policykit-0.9_8:  20%Using existing group 'polkit'.
[51/143] Extracting policykit-0.9_8:  30%Using existing user 'polkit'.
[51/143] Extracting policykit-0.9_8:  96%
pkg: cannot rename /usr/local/share/dbus-1/interfaces/org.freedesktop.PolicyKit.AuthenticationAgent.xml.o0SLw5j9ZZH2 to /usr/local/share/dbus-1/interfaces/org.freedesktop.PolicyKit.AuthenticationAgent.xml: Operation not permitted
[51/143] Extracting policykit-0.9_8: 100%
[51/143] Deleting files for policykit-0.9_8: 100%

So I used truss just to confirm that it was actually a rename failing:

 1023: lstat("/usr/local/share/dbus-1/interfaces/org.freedesktop.PolicyKit.AuthenticationAgent.xml",{ mode=-rw-r--r-- ,inode=5841736,size=886,blksize=16384 }) = 0 (0x0)
 1023: umask(0x0,0x289d6430,0x61,0x28450637,0xbfbfd4a4,0x286feee1) = 18 (0x12)
 1023: open("/usr/local/share/dbus-1/interfaces/org.freedesktop.PolicyKit.AuthenticationAgent.xml.o0SLw5j9ZZH2",O_WRONLY|O_CREAT|O_EXCL,0644) = 28 (0x1c)
 1023: umask(0x12,0x289d6430,0x61,0x28450637,0xbfbfd4a4,0x286feee1) = 0 (0x0)
 1023: write(28,"<!DOCTYPE node PUBLIC "-//freede"...,886) = 886 (0x376)
 1023: fchown(0x1c,0x0,0x0,0x2845051f,0x0,0x2ef01200) = 0 (0x0)
 1023: futimes(28,{1421842201.000000 })          = 0 (0x0)
 1023: close(28)                                 = 0 (0x0)
 1023: ioctl(1,TIOCGETA,0xbfbfcde0)              = 0 (0x0)
 1023: write(1,"\r[51/143] Extracting policykit-"...,42) = 42 (0x2a)
 1023: chflags("/usr/local/share/dbus-1/interfaces/org.freedesktop.PolicyKit.AuthenticationAgent.xml.o0SLw5j9ZZH2",0x51512e68) = 0 (0x0)
 1023: lstat("/usr/local/share/dbus-1/interfaces/org.freedesktop.PolicyKit.AuthenticationAgent.xml",{ mode=-rw-r--r-- ,inode=5841736,size=886,blksize=16384 }) = 0 (0x0)
 1023: rename("/usr/local/share/dbus-1/interfaces/org.freedesktop.PolicyKit.AuthenticationAgent.xml.o0SLw5j9ZZH2","/usr/local/share/dbus-1/interfaces/org.freedesktop.PolicyKit.AuthenticationAgent.xml") ERR#1 'Operation not permitted'
 1023: chflags("/usr/local/share/dbus-1/interfaces/org.freedesktop.PolicyKit.AuthenticationAgent.xml",0x0) = 0 (0x0)
 1023: write(1,"\n",1)                           = 1 (0x1)
 1023: write(2,"pkg: ",5)                        = 5 (0x5)
 1023: write(2,"cannot rename /usr/local/share/d"...,224) = 224 (0xe0)
 1023: write(2,"\n",1)                           = 1 (0x1)
 1023: ioctl(1,TIOCGETA,0xbfbfcde0)              = 0 (0x0)
 1023: write(1,"\r[51/143] Extracting policykit-"...,42) = 42 (0x2a)
 1023: ioctl(1,TIOCGETA,0xbfbfcdd0)              = 0 (0x0)
 1023: write(1,"\n",1)                           = 1 (0x1)
 1023: chflags("/usr/local/share/dbus-1/interfaces/org.freedesktop.PolicyKit.AuthenticationAgent.xml.o0SLw5j9ZZH2",0x51512e68) = 0 (0x0)
 1023: unlink("/usr/local/share/dbus-1/interfaces/org.freedesktop.PolicyKit.AuthenticationAgent.xml.o0SLw5j9ZZH2") ERR#1 'Operation not permitted'

So I thought I'd check the flags for the files in that directory:

/usr/local/share/dbus-1/interfaces # ls -lo
total 48
-rw-r--r--  1 root  wheel  -                  14059  3 Dec 07:07 org.freedesktop.ConsoleKit.Manager.xml
-rw-r--r--  1 root  wheel  -                   5304  3 Dec 07:07 org.freedesktop.ConsoleKit.Seat.xml
-rw-r--r--  1 root  wheel  -                  16704  3 Dec 07:07 org.freedesktop.ConsoleKit.Session.xml
-rw-r--r--  1 root  wheel  sunlnk,opaque        886 18 Dec 07:24 org.freedesktop.PolicyKit.AuthenticationAgent.xml.ZHo5MP2djohN
-rw-r--r--  1 root  wheel  arch,sunlnk,opaque   886 18 Dec 07:24 org.freedesktop.PolicyKit.AuthenticationAgent.xml.o0SLw5j9ZZH2

So it has the sunlnk flag set on the temporary file. And just to confirm this is the problem:

/usr/local/share/dbus-1/interfaces # mv org.freedesktop.PolicyKit.AuthenticationAgent.xml.o0SLw5j9ZZH2 org.freedesktop.PolicyKit.AuthenticationAgent.xml
mv: rename org.freedesktop.PolicyKit.AuthenticationAgent.xml.o0SLw5j9ZZH2 to org.freedesktop.PolicyKit.AuthenticationAgent.xml: Operation not permitted
/usr/local/share/dbus-1/interfaces # chflags nosunlnk org.freedesktop.PolicyKit.AuthenticationAgent.xml.o0SLw5j9ZZH2
/usr/local/share/dbus-1/interfaces # mv org.freedesktop.PolicyKit.AuthenticationAgent.xml.o0SLw5j9ZZH2 org.freedesktop.PolicyKit.AuthenticationAgent.xml
/usr/local/share/dbus-1/interfaces # ls -lo
total 48
-rw-r--r--  1 root  wheel  -             14059  3 Dec 07:07 org.freedesktop.ConsoleKit.Manager.xml
-rw-r--r--  1 root  wheel  -              5304  3 Dec 07:07 org.freedesktop.ConsoleKit.Seat.xml
-rw-r--r--  1 root  wheel  -             16704  3 Dec 07:07 org.freedesktop.ConsoleKit.Session.xml
-rw-r--r--  1 root  wheel  arch,opaque     886 18 Dec 07:24 org.freedesktop.PolicyKit.AuthenticationAgent.xml
-rw-r--r--  1 root  wheel  sunlnk,opaque   886 18 Dec 07:24 org.freedesktop.PolicyKit.AuthenticationAgent.xml.ZHo5MP2djohN

So how did the sunlnk flag get there in the first place? Is this a bug? There seem to have been a number of changes to https://github.com/freebsd/pkg/commits/1.4.6/libpkg/pkg_add.c recently in this area so hopefully @bapt has some ideas what's going on.

Happy to provide further info.

[tdb]

It looks to me like the files are coming out of the archive with various flags set. Is that expected behaviour? Is it a libarchive bug, and if so, is it during the creation or extraction stage?

I can somewhat work around it by doing:

diff --git a/libpkg/pkg_add.c b/libpkg/pkg_add.c
index b64c948..ae0c8da 100644
--- a/libpkg/pkg_add.c
+++ b/libpkg/pkg_add.c
@@ -42,7 +42,7 @@
 #include "private/pkg.h"
 #include "private/pkgdb.h"

-#define NOCHANGESFLAGS (UF_IMMUTABLE | UF_APPEND | SF_IMMUTABLE | SF_APPEND)
+#define NOCHANGESFLAGS (UF_IMMUTABLE | UF_APPEND | UF_NOUNLINK | SF_IMMUTABLE | SF_APPEND | SF_NOUNLINK)


 static const unsigned char litchar[] =

But this results in files in the filesystem afterwards having a whole bunch of flags set, which probably isn't wanted? For example:

# ls -lo /usr/local/bin/pg_dump
-rwxr-xr-x  1 root  wheel  sappnd,arch,schg,sunlnk,uappnd,nodump,uunlnk 304896  6 Jan 12:17 /usr/local/bin/pg_dump

[tdb]

I'm also not sure about this line: https://github.com/freebsd/pkg/blob/master/libpkg/pkg_add.c#L287

Should it be restoring the flags of the original file or the file from the archive?

I think that's all I've got on this. Hopefully it helps a bit.

[bapt]

it helps a lot thanks
I'm investigating!

[bapt]

Right that should be fixed in, will be in 1.4.7.

I'll do more testing before releasing.

I would appreciate if you could test (the branch for 1.4.7 is: release-1.4)

[tdb]

@bapt Happy to test. Will there be a ports-mgmt/pkg-devel with the changes, or do I need to pull from git?

[tdb]

Looks good to me. At least, no errors at all in a full pkg upgrade -f, which reliably failed before. Thanks!

Actually - I take that back. I noticed a number of files in /usr/local with odd flags set. So I need to clean things up and make sure there's no previous mess lying around and try again. Will feed back tomorrow.

[tdb]

@bapt Ok, further testing this morning has still revealed problems. The first problem is that during a forced upgrade (so when a rename happens), I get files with odd flags. Here's a before and after for a pkg upgrade -f:

-rwxr-xr-x   1 root    wheel       -                   40184  6 Jan 12:17 /usr/local/bin/createdb
-rwxr-xr-x   1 root    wheel       sappnd,arch,schg,sunlnk,uappnd,nodump,uunlnk         40184  6 Jan 12:17 /usr/local/bin/createdb

I think this is because of https://github.com/freebsd/pkg/blob/release-1.4/libpkg/pkg_add.c#L287 - in the case of a rename you apply the flags from the stat of the file within the archive, but you don't for a non-rename. Is that right?

The second problem is that I still get failures, but from archive_read_extract(). They're not consistent; it fails in different places, and sometimes not at all. But here's traces of some failures:

[84/342] Reinstalling gcc-4.8.4...
[84/342] Extracting gcc-4.8.4:   0%
pkg-static: archive_read_extract(): Can't create '/usr/local/bin/gcj48.UBhwsiDIAO1j'
[84/342] Extracting gcc-4.8.4: 100%
[84/342] Deleting files for gcc-4.8.4: 100%

 1307: link("/usr/local/bin/i386-portbld-freebsd8.4-gcj48","/usr/local/bin/gcj48.URZLhWM6IQsr") ERR#1 'Operation not permitted'
 1307: umask(0x12,0x0,0x0,0x28adb200,0x0,0x0)    = 0 (0x0)
 1307: write(1,"\n",1)                           = 1 (0x1)
 1307: write(2,"pkg-static: ",12)                = 12 (0xc)
 1307: write(2,"archive_read_extract(): Can't cr"...,72) = 72 (0x48)
 1307: write(2,"\n",1)                           = 1 (0x1)
 1307: ioctl(1,TIOCGETA,0xbfbfd548)              = 0 (0x0)
 1307: write(1,"\r[84/342] Extracting gcc-4.8.4:"...,36) = 36 (0x24)
 1307: ioctl(1,TIOCGETA,0xbfbfd538)              = 0 (0x0)
 1307: write(1,"\n",1)                           = 1 (0x1)
 1307: chflags("/usr/local/bin/gcj48.URZLhWM6IQsr",0x28) ERR#2 'No such file or directory'
 1307: unlink("/usr/local/bin/gcj48.URZLhWM6IQsr") ERR#2 'No such file or directory'
 1307: clock_gettime(13,{1422013652.000000000 }) = 0 (0x0)
 1307: ioctl(1,TIOCGETA,0xbfbfd558)              = 0 (0x0)
 1307: write(1,"[84/342] Deleting files for gcc-"...,43) = 43 (0x2b)
 1307: ioctl(1,TIOCGETA,0xbfbfd508)              = 0 (0x0)
 1307: write(1,"\r[84/342] Deleting files for gc"...,44) = 44 (0x2c)

[61/342] Reinstalling binutils-2.25...
[61/342] Extracting binutils-2.25:   5%
pkg-static: archive_read_extract(): Can't create '/usr/local/bin/ld.bfd.f845HuNqe9qg'
[61/342] Extracting binutils-2.25: 100%
[61/342] Deleting files for binutils-2.25: 100%

 1589: lstat("/usr/local/bin/ld.bfd",{ mode=-r-xr-xr-x ,inode=380045,size=971948,blksize=16384 }) = 0 (0x0)
 1589: umask(0x0,0x2effc100,0x22,0x837e178,0x0,0x0) = 18 (0x12)
 1589: link("/usr/local/bin/ld","/usr/local/bin/ld.bfd.f845HuNqe9qg") ERR#1 'Operation not permitted'
 1589: umask(0x12,0x0,0x0,0x31afd100,0x0,0x0)    = 0 (0x0)
 1589: write(1,"\n",1)                           = 1 (0x1)
 1589: write(2,"pkg-static: ",12)                = 12 (0xc)
 1589: write(2,"archive_read_extract(): Can't cr"...,73) = 73 (0x49)
 1589: write(2,"\n",1)                           = 1 (0x1)
 1589: ioctl(1,TIOCGETA,0xbfbfd548)              = 0 (0x0)
 1589: write(1,"\r[61/342] Extracting binutils-2"...,40) = 40 (0x28)
 1589: ioctl(1,TIOCGETA,0xbfbfd538)              = 0 (0x0)
 1589: write(1,"\n",1)                           = 1 (0x1)
 1589: chflags("/usr/local/bin/ld.bfd.f845HuNqe9qg",0x10101) ERR#2 'No such file or directory'
 1589: unlink("/usr/local/bin/ld.bfd.f845HuNqe9qg") ERR#2 'No such file or directory'
 1589: clock_gettime(13,{1422013975.000000000 }) = 0 (0x0)
 1589: ioctl(1,TIOCGETA,0xbfbfd558)              = 0 (0x0)
 1589: write(1,"[61/342] Deleting files for binu"...,47) = 47 (0x2f)
 1589: ioctl(1,TIOCGETA,0xbfbfd508)              = 0 (0x0)
 1589: write(1,"\r[61/342] Deleting files for bi"...,48) = 48 (0x30)
 1589: open("/",0x120000,02000)                  = 11 (0xb)

Interestingly both cases are calls to link(). I've not seen a failure for anything else. I suspect this is the problem:

     [EPERM]            The file named by name1 has its immutable or append-
                        only flag set, see the chflags(2) manual page for more
                        information.

So probably caused by the target of the link having some flags set?

Again, happy to do more testing while I have a repeatedly broken setup!

[bapt]

Right so now I'm completly lost, I bet the problem is from libarchive 2.8 which is the version on FreeBSD 8 and some incompatibilities with libarchive 3 as I cannot reproduce on FreeBSD 9 or 10.

Somehow the flags from the archive are not real flags.

Maybe I should just skip all the flag handling on libarchive 2.8, I'll try to come with a patch

[tdb]

Yes, I was beginning to wonder if libarchive was giving garbage flags, or more specifically that archive_entry_stat is returning garbage. You only use aest->st_flags for a rename, which might be why it's only on upgrades rather than installs that I see the problem?

I suppose you want to be able to support files with flags in packages? If you don't, just wipe all flags?

[bapt]

I only use aest->st_flags for a rename because to be able to handle the rename I need to wipe out the flags first. On all other cases libarchive should directly have extracted the proper flags.

Yes we need to be able to support files with flags in packages to be able to package base.

[bapt]

This time it should be really fixed. Really sorry about that breakage...

[tdb]

@bapt fixed, thank you! No problems doing the upgrade, and no unexpected flags on files afterwards.