bin/126301: pkg_version can induce unexpected parsing of INDEX

Wed Aug 6 13:10:02 UTC 2008

>Number:         126301
>Category:       bin
>Synopsis:       pkg_version can induce unexpected parsing of INDEX
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    freebsd-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Wed Aug 06 13:10:01 UTC 2008
>Closed-Date:
>Last-Modified:
>Originator:     Jeremy Chadwick
>Release:        FreeBSD 8.0-CURRENT i386
>Organization:
>Environment:
System: FreeBSD casper.daemonic.se 8.0-CURRENT FreeBSD 8.0-CURRENT #0: Wed Aug  6 00:35:20 CEST 2008     root at casper.daemonic.se:/usr/obj/usr/src/sys/CASPER   i386
>Description:
	An individual on EFnet #bsdports (cc'd) was reporting that pkg_version was
	indefinitely hanging for him, and I offered to figure out why.  Upon using
	truss -f -s 2048 -a -d -o truss2.out pkg_version, he got back 12MBytes
	of truss output, and pkg_version never completed.

	Based upon the truss output, it became apparent where the slowdown was:
	INDEX was being read and parsed.  The user did not use pkg_version -I.

	It appears that pkg_version will automatically start reading the INDEX
	file if "/usr/bin/make -V PKGNAME" fails, or claims to fail.  The
	error-handing conditional is where I believe the problem is.  The code
	which calls vpipe() to read the output from the make command is in
	usr.sbin/pkg_install/version/perform.c, function pkg_do.

	Function vpipe() is declared in lib/exec.c.  Look near the end:

    if (pclose(fp) || (strlen(rp) == 0)) {
        free(rp);
        return NULL;
    }

	I believe the if() conditional around pclose(fp) is incorrect for
	handling situations where wait4(2) returns something expected; meaning
	there might not be an error situation at all.

	It's entirely possible the situation which occurred is *really* the
	result of an error (problem with the system, etc.), so the truss output
	below needs review by someone who can understand it better.  (I'm also
	not sure why it took 1.2 full seconds for fstat() to finish and read()
	to start...)

>How-To-Repeat:
	Not easily reproducable, but I've included output from truss below.
	I believe it demonstrates the situation:

 1041: 0.443486254 open("/var/db/pkg/expat-2.0.1/+CONTENTS",O_RDONLY,0666) = 5 (0x5)
 1041: 0.446424337 fstat(5,{ mode=-rw-r--r-- ,inode=16609,size=801,blksize=4096 }) = 0 (0x0)
 1041: 0.446960997 read(5,"@comment PKG_FORMAT_REVISION:1.1\n at name expat-2.0.1\n at comment ORIGIN:textproc/expat2\n at cwd /usr/local\nman/man1/xmlwf.1.gz\n at comment MD5:2c1bfd188c4734c56a5b23bdfa8a5d86\n at unexec rm -f %D/man/cat1/xmlwf.1.gz %D/man/cat1/xmlwf.1 %D/man/cat1/xmlwf.1.gz %D/man/cat1/xmlwf.1.gz.gz %D/man/cat1/xmlwf.1.gz.bz2\nbin/xmlwf\n at comment MD5:843f4e4d077ebce8afc950477a50bd3c\ninclude/expat.h\n at comment MD5:f235455608da0e14424b2cba731be0c6\ninclude/expat_external.h\n at comment MD5:8e2b8dce543d6ff4cdb37f4a8daabd9e\nlib/libexpat.a\n at comment MD5:58956db16e327d58e68b2de511db53fa\nlib/libexpat.la\n at comment MD5:39bbac9c6a1dc750d466e1b9b45aa996\nlib/libexpat.so\n at comment MD5:09edb1d6b84068894c992ae9c3ca38b7\nlib/libexpat.so.6\n at comment MD5:9761cea33fb8af25c66d5f2ca25aabe6\n at exec /sbin/ldconfig -m /usr/local/lib\n at unexec /sbin/ldconfig -R\n",4096) = 801 (0x321)
 1041: 0.447806915 read(5,0x810f000,4096)        = 0 (0x0)
 1041: 0.448243283 close(5)                      = 0 (0x0)
 1041: 0.492636914 lstat("/usr/ports/textproc/expat2",{ mode=drwxr-xr-x ,inode=150562,size=512,blksize=4096 }) = 0 (0x0)
 1041: 0.493274984 chdir("/usr/ports/textproc/expat2") = 0 (0x0)
 1041: 0.522788791 stat("Makefile",{ mode=-rw-r--r-- ,inode=147954,size=855,blksize=4096 }) = 0 (0x0)
 1041: 0.523325172 __sysctl(0xbfbfe018,0x2,0xbfbfe024,0xbfbfe028,0x0,0x0) = 0 (0x0)
 1041: 0.524371953 pipe(0xbfbbe034,0x2b,0x0,0x0,0x11,0x28085a00) = 5 (0x5)
 1041: 0.554063436 vfork(0x2b,0x0,0x0,0x11,0x81091a0,0x0) = 1042 (0x412)
 1041: 0.558099424 fcntl(5,F_GETFL,)             = 2 (0x2)
 1041: 0.558928300 close(6)                      = 0 (0x0)
 1041: 0.559348745 fstat(5,{ mode=p--------- ,inode=0,size=0,blksize=4096 }) = 0 (0x0)
 1041: 1.705575150 read(5,"expat-2.0.1\n",4096)  = 12 (0xc)
 1041: 1.706261271 close(5)                      = 0 (0x0)
 1041: 1.706812459 wait4(0x412,0xbfbbe038,0x0,0x0,0x804ec35,0xbfbfe078) ERR#10 'No child processes'
 1041: 1.707651951 write(2,"pkg_version: ",13)   = 13 (0xd)
 1041: 1.708126313 write(2,"Failed to get PKGNAME from /usr/ports/textproc/expat2/Makefile!",63) = 63 (0x3f)
 1041: 1.708703760 write(2,"\n",1)               = 1 (0x1)
 1041: 1.709128954 fstat(4,{ mode=-rw-r--r-- ,inode=23575,size=23671504,blksize=4096 }) = 1042 (0x412)
 1042: 1.131604156 wait4(0xffffffff,0xbfbfeb18,0x2,0x0,0x213,0x1) = 1043 (0x413)
 1042: 1.131604156 process exit, rval = 0
 = 0 (0x0)

>Fix:
	IMPORTANT NOTE: This needs review from those who are more familiar with
	popen() and pclose() than I am; des@ comes to mind.  :-)  I am in no
	way a "guru" with these functions.

	I believe the call to pclose(fp) needs to be wrapped with the WIFEXITED()
	and WEXITSTATUS() macros, as listed in the wait4(2) manpage.  Something
	like this might suffice (untested):

    int exitcode;

    exitcode = pclose(fp);

    if (!WIFEXITED(exitcode) || (WEXITSTATUS(status) != 0) || (strlen(rp) == 0)) {
        free(rp);
        return NULL;
    }

>Release-Note:
>Audit-Trail:
>Unformatted: