{"id":124,"date":"2011-08-02T03:48:35","date_gmt":"2011-08-02T09:48:35","guid":{"rendered":"http:\/\/www.mariovaldez.net\/webapps\/blog\/?p=124"},"modified":"2011-08-20T02:17:20","modified_gmt":"2011-08-20T08:17:20","slug":"php-unlink-cannot-delete-file","status":"publish","type":"post","link":"https:\/\/www.mariovaldez.net\/webapps\/blog\/2011\/08\/02\/php-unlink-cannot-delete-file\/","title":{"rendered":"PHP unlink cannot delete file"},"content":{"rendered":"<p>How I fixed a PHP&#8217;s unlink function problem in my development server using strace to debug PHP&#8230;<br \/>\nand why libtrash should not be used by the Apache user.<\/p>\n<p><!--more--><\/p>\n<p>Since 2004 my development server have been having a weird problem. Sometimes, in PHP, the <em>unlink<\/em> functions starts to fail. It fails to delete some files. The permissions were right. The files were not locked. It just failed. In some older versions of PHP, unlink even returned true (meaning it successfully deleted the file) while displaying a warning saying: <em>Warning: unlink(FileName) [function.unlink]: Success in ScriptName on line X<\/em>. Yeah, it says <em>success<\/em> in a warning.<\/p>\n<p>The first time it happened I was really puzzled. I spent two days trying to figure out what was the problem. I searched high and low the web for similar problems but found nothing. Was I the only person with this problem? Maybe, I thought. My development server is a Slackware server with too many customized applications and version combinations not found in other distributions. With so much customization (configuration, kernel, software versions) this Slackware version is now unique and its problems are sometimes unique too. So, the problem could be anywhere from the higher parts of the web stack (Apache and PHP) to the lower parts like the C library or the kernel. And that&#8217;s why I also didn&#8217;t send a bug report in PHP: I was not sure this was a PHP problem.<\/p>\n<p>Anyway, I found rebooting fixed the problem. Of course I didn&#8217;t try to reboot to fix it (c&#8217;mon, this is not Windows), but since I was recompiling the kernel to test different file system options, I needed to reboot. Because of its sporadic nature, I could not replicate the problem at will, sometimes it appeared again after weeks or months. I started to learn to live with it.<\/p>\n<p>So, last Monday it happened again. After almost 7 years, here I was again, facing this <em>unlink<\/em> which refused to delete and yet it claimed success. I decided I was going to find the cause today. So I decided to do what I should have done before: I will debug PHP.<\/p>\n<p>But before recompiling PHP with debug information and using gdb, I decided to start with something easier: <em>strace<\/em>.<\/p>\n<p>This is what I did:<\/p>\n<p><strong>Step 1:<\/strong> I created a test PHP script:<\/p>\n<pre>\r\nunlink (\"\/home\/mvaldez\/SHARE\/DEV-www\/eclipse\/inovman2old\/backups\/backup_20110801_100336_dump.txt.bz2\"); \r\n<\/pre>\n<p><strong>Step 2:<\/strong> I stopped Apache.<\/p>\n<pre>\/etc\/rc.d\/rc.httpd stop<\/pre>\n<p><strong>Step 3:<\/strong> I started Apache in debug mode:<\/p>\n<pre>\/usr\/apache\/bin\/apachectl -X<\/pre>\n<p><strong>Step 4:<\/strong> I used <em>ps<\/em> to find out what is the PID of the httpd process:<\/p>\n<pre>ps auxw | grep http\r\n\r\nnobody   25908  1.4  0.1 242360 14360 pts\/1    S+   14:20   0:00 \/usr\/apache\/bin\/httpd -X\r\nroot     26529  0.0  0.0   8720   744 pts\/2    R+   14:20   0:00 grep http<\/pre>\n<p><strong>Step 5:<\/strong> I started strace attached to that process:<\/p>\n<pre>strace -p 25908\r\n\r\nProcess 25908 attached - interrupt to quit\r\nepoll_wait(16, {{EPOLLIN, {u32=19153432, u64=19153432}}}, 2, 4294967295) = 1\r\n<\/pre>\n<p><strong>Step 6:<\/strong> In my workstation, I launched <em>links<\/em>, a text-only web browser (I could have used <em>lynx<\/em>, <em>wget<\/em> or even a graphical web browser).<\/p>\n<pre>links http:\/\/192.168.246.1\/dev\/dev\/testfiles\/unlinktest\/u.php<\/pre>\n<p>I received the usual message:<br \/>\n<em>Warning: unlink(\/home\/mvaldez\/SHARE\/DEV-www\/eclipse\/inovman2old\/backups\/backup_20110801_100336_dump.txt.bz2)<br \/>\n[function.unlink]: Success in \/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/u.php on line 3<\/em><\/p>\n<p>And this was the strace output (note the highlighted lines):<\/p>\n<p><code>accept(4, {sa_family=AF_INET6, sin6_port=htons(52039), inet_pton(AF_INET6, \"::ffff:192.168.246.25\", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 17<br \/>\nfcntl(17, F_GETFD)                      = 0<br \/>\nfcntl(17, F_SETFD, FD_CLOEXEC)          = 0<br \/>\nsemop(2555917, 0x7f9a88b8deec, 1)       = 0<br \/>\ngetsockname(17, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, \"::ffff:192.168.246.1\", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [68719476764]) = 0<br \/>\nfcntl(17, F_GETFL)                      = 0x2 (flags O_RDWR)<br \/>\nfcntl(17, F_SETFL, O_RDWR|O_NONBLOCK)   = 0<br \/>\nread(17, \"GET \/dev\/testfiles\/unlinktest\/u.p\"..., 8000) = 669<br \/>\nstat(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/u.php\", {st_mode=S_IFREG|0744, st_size=113, ...}) = 0<br \/>\nopen(\"\/.htaccess\", O_RDONLY|O_CLOEXEC)  = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/mvaldez\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/DEV-www\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/u.php\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOTDIR (Not a directory)<br \/>\nsetitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0<br \/>\nrt_sigaction(SIGPROF, {0x7f9a81552ec0, [PROF], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, {0x7f9a81552ec0, [PROF], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, 8) = 0<br \/>\nrt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0<br \/>\nrt_sigaction(SIGSEGV, {0x7f9a7e27bd60, [SEGV], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, {SIG_DFL, [SEGV], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, 8) = 0<br \/>\nrt_sigaction(SIGFPE, {0x7f9a7e27bd60, [FPE], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, {SIG_DFL, [FPE], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, 8) = 0<br \/>\nrt_sigaction(SIGBUS, {0x7f9a7e27bd60, [BUS], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, {SIG_DFL, [BUS], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, 8) = 0<br \/>\nrt_sigaction(SIGILL, {0x7f9a7e27bd60, [ILL], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, {SIG_DFL, [ILL], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, 8) = 0<br \/>\nrt_sigaction(SIGABRT, {0x7f9a7e27bd60, [ABRT], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, {SIG_DFL, [ABRT], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, 8) = 0<br \/>\ngetcwd(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\"..., 4095) = 49<br \/>\nchdir(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\") = 0<br \/>\nsetitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/u.php\", O_RDONLY) = 18<br \/>\nfstat(18, {st_mode=S_IFREG|0744, st_size=113, ...}) = 0<br \/>\nmmap(NULL, 113, PROT_READ, MAP_SHARED, 18, 0) = 0x7f9a8a671000<br \/>\nmunmap(0x7f9a8a671000, 113)             = 0<br \/>\nclose(18)                               = 0<br \/>\nstat(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/u.php\", {st_mode=S_IFREG|0744, st_size=113, ...}) = 0<br \/>\nstat(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/u.php\", {st_mode=S_IFREG|0744, st_size=113, ...}) = 0<br \/>\nwrite(2, \"EACCELERATOR hit: \\\"\/home\/mvaldez\/\"..., 75) = 75<br \/>\ngeteuid()                               = 99<br \/>\nopen(\"\/etc\/passwd\", O_RDONLY|O_CLOEXEC) = 18<br \/>\nlseek(18, 0, SEEK_CUR)                  = 0<br \/>\nfstat(18, {st_mode=S_IFREG|0644, st_size=1959, ...}) = 0<br \/>\nmmap(NULL, 1959, PROT_READ, MAP_SHARED, 18, 0) = 0x7f9a8a671000<br \/>\nlseek(18, 1959, SEEK_SET)               = 1959<br \/>\nmunmap(0x7f9a8a671000, 1959)            = 0<br \/>\nclose(18)                               = 0<br \/>\n<strong>open(\"\/\/.libtrash\", O_RDONLY)           = -1 ENOENT (No such file or directory)<\/strong><br \/>\ngeteuid()                               = 99<br \/>\nopen(\"\/etc\/passwd\", O_RDONLY|O_CLOEXEC) = 18<br \/>\nlseek(18, 0, SEEK_CUR)                  = 0<br \/>\nfstat(18, {st_mode=S_IFREG|0644, st_size=1959, ...}) = 0<br \/>\nmmap(NULL, 1959, PROT_READ, MAP_SHARED, 18, 0) = 0x7f9a8a671000<br \/>\nlseek(18, 1959, SEEK_SET)               = 1959<br \/>\nmunmap(0x7f9a8a671000, 1959)            = 0<br \/>\nclose(18)                               = 0<br \/>\ngeteuid()                               = 99<br \/>\nopen(\"\/etc\/passwd\", O_RDONLY|O_CLOEXEC) = 18<br \/>\nlseek(18, 0, SEEK_CUR)                  = 0<br \/>\nfstat(18, {st_mode=S_IFREG|0644, st_size=1959, ...}) = 0<br \/>\nmmap(NULL, 1959, PROT_READ, MAP_SHARED, 18, 0) = 0x7f9a8a671000<br \/>\nlseek(18, 1959, SEEK_SET)               = 1959<br \/>\nmunmap(0x7f9a8a671000, 1959)            = 0<br \/>\nclose(18)                               = 0<br \/>\n<strong>stat(\"\/\/Recycled\", 0x7fff717bb300)      = -1 ENOENT (No such file or directory)<br \/>\nmkdir(\"\/\/Recycled\", 0700)               = -1 EACCES (Permission denied)<\/strong><br \/>\nwrite(2, \"[Mon Aug 01 14:28:26 2011] [error\"..., 298) = 298<br \/>\nchdir(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\") = 0<br \/>\nrt_sigaction(SIGSEGV, {SIG_DFL, [SEGV], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, {0x7f9a7e27bd60, [SEGV], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, 8) = 0<br \/>\nrt_sigaction(SIGFPE, {SIG_DFL, [FPE], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, {0x7f9a7e27bd60, [FPE], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, 8) = 0<br \/>\nrt_sigaction(SIGBUS, {SIG_DFL, [BUS], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, {0x7f9a7e27bd60, [BUS], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, 8) = 0<br \/>\nrt_sigaction(SIGILL, {SIG_DFL, [ILL], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, {0x7f9a7e27bd60, [ILL], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, 8) = 0<br \/>\nrt_sigaction(SIGABRT, {SIG_DFL, [ABRT], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, {0x7f9a7e27bd60, [ABRT], SA_RESTORER|SA_RESTART, 0x7f9a87bc2f30}, 8) = 0<br \/>\nopen(\"\/dev\/urandom\", O_RDONLY)          = 18<br \/>\nread(18, \"\\361\\303C\\\"\\255\\337Cs\"..., 8) = 8<br \/>\nclose(18)                               = 0<br \/>\nopen(\"\/dev\/urandom\", O_RDONLY)          = 18<br \/>\nread(18, \"l!3\\273]Y\\356\\231\"..., 8)     = 8<br \/>\nclose(18)                               = 0<br \/>\nopen(\"\/dev\/urandom\", O_RDONLY)          = 18<br \/>\nread(18, \"kHNK\\303\\277\\37#\"..., 8)      = 8<br \/>\nclose(18)                               = 0<br \/>\nsetitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0<br \/>\nwritev(17, [{\"HTTP\/1.1 200 OK\\r\\nDate: Mon, 01 Au\"..., 279}, {\"&lt;br \/&gt;\\n&lt;b&gt;Warning&lt;\/b&gt;:  unlink(\/h\"..., 269}], 2) = 548<br \/>\nread(17, 0x1257208, 8000)               = -1 EAGAIN (Resource temporarily unavailable)<br \/>\nwrite(9, \"192.168.246.25 - - [01\/Aug\/2011:1\"..., 103) = 103<br \/>\nwrite(10, \"referer\\n\"..., 8)            = 8<br \/>\nwrite(11, \"agent\\n\"..., 6)              = 6<br \/>\nwrite(12, \"192.168.246.25 - - [01\/Aug\/2011:1\"..., 161) = 161<br \/>\npoll([{fd=17, events=POLLIN}], 1, 15000<br \/>\n<\/code><\/p>\n<p>The call to the libc <em>unlink<\/em> never happened, instead we can see a failed attempt to read a <em>.libtrash<\/em> directory and then create a <em>Recycled<\/em> directory in the home directory of the Apache user (which in this server is the user <em>nobody<\/em>, which home is the file system root <em>\/<\/em>). Ok, now it makes sense: the <em>.libtrash<\/em> directory is the configuration directory of <em>libtrash<\/em> (<a href=\"http:\/\/pages.stern.nyu.edu\/~marriaga\/software\/libtrash\/\">http:\/\/pages.stern.nyu.edu\/~marriaga\/software\/libtrash\/<\/a>), a library for Linux which can be preloaded to intercept calls to GNU libc <em>unlink<\/em> (among other functions) so that deleted files are moved to a <em>trash can<\/em> directory from where you can recover deleted files if you wish. The <em>Recycled<\/em> directory is the name of the trash can directory as configured in this server.<\/p>\n<p>Soooo, my hypothesis by now was that <em>libtrash<\/em> was intercepting the call to libc <em>unlink<\/em> made by PHP but then failed, because the <em>nobody<\/em> user has no appropriate home directory.<\/p>\n<p><strong>Step 7:<\/strong> As the loading of the <em>libtrash<\/em> is done in <em>\/etc\/profile.d\/default.sh<\/em> (in this server) for all users by exporting the <em>LD_PRELOAD<\/em> variable, to test I just need to unset it in my current session and then load Apache again:<\/p>\n<pre>unset LD_PRELOAD\r\n\/usr\/apache\/bin\/apachectl -X<\/pre>\n<p><strong>Step 8:<\/strong> Now, let&#8217;s run strace and reload the PHP script. This was the strace output now (note the highlighted line):<\/p>\n<p><code>Process 18951 attached - interrupt to quit<br \/>\nepoll_wait(16, {{EPOLLIN, {u32=34029016, u64=34029016}}}, 2, 4294967295) = 1<br \/>\naccept(4, {sa_family=AF_INET6, sin6_port=htons(35245), inet_pton(AF_INET6, \"::ffff:192.168.246.25\", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [140733193388060]) = 17<br \/>\nfcntl(17, F_GETFD)                      = 0<br \/>\nfcntl(17, F_SETFD, FD_CLOEXEC)          = 0<br \/>\nsemop(2752525, 0x7eff72b37eec, 1)       = 0<br \/>\ngetsockname(17, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, \"::ffff:192.168.246.1\", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [68719476764]) = 0<br \/>\nfcntl(17, F_GETFL)                      = 0x2 (flags O_RDWR)<br \/>\nfcntl(17, F_SETFL, O_RDWR|O_NONBLOCK)   = 0<br \/>\nread(17, \"GET \/dev\/testfiles\/unlinktest\/u.p\"..., 8000) = 626<br \/>\nstat(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/u.php\", {st_mode=S_IFREG|0744, st_size=113, ...}) = 0<br \/>\nopen(\"\/.htaccess\", O_RDONLY|O_CLOEXEC)  = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/mvaldez\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/DEV-www\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/u.php\/.htaccess\", O_RDONLY|O_CLOEXEC) = -1 ENOTDIR (Not a directory)<br \/>\nmmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7eff74392000<br \/>\nsetitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0<br \/>\nrt_sigaction(SIGPROF, {0x7eff6b4fcec0, [PROF], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, {SIG_DFL, [], 0}, 8) = 0<br \/>\nrt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0<br \/>\nrt_sigaction(SIGSEGV, {0x7eff68225d60, [SEGV], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, {SIG_DFL, [], 0}, 8) = 0<br \/>\nrt_sigaction(SIGFPE, {0x7eff68225d60, [FPE], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, {SIG_DFL, [], 0}, 8) = 0<br \/>\nrt_sigaction(SIGBUS, {0x7eff68225d60, [BUS], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, {SIG_DFL, [], 0}, 8) = 0<br \/>\nrt_sigaction(SIGILL, {0x7eff68225d60, [ILL], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, {SIG_DFL, [], 0}, 8) = 0<br \/>\nrt_sigaction(SIGABRT, {0x7eff68225d60, [ABRT], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, {SIG_DFL, [], 0}, 8) = 0<br \/>\ngetcwd(\"\/root\"..., 4095)                = 6<br \/>\nchdir(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\") = 0<br \/>\nsetitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/u.php\", O_RDONLY) = 18<br \/>\nfstat(18, {st_mode=S_IFREG|0744, st_size=113, ...}) = 0<br \/>\nmmap(NULL, 113, PROT_READ, MAP_SHARED, 18, 0) = 0x7eff74391000<br \/>\nmunmap(0x7eff74391000, 113)             = 0<br \/>\nclose(18)                               = 0<br \/>\nstat(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/u.php\", {st_mode=S_IFREG|0744, st_size=113, ...}) = 0<br \/>\nopen(\"\/tmp\/eaccelerator\/4\/3\/eaccelerator-9032.9315914\", O_RDONLY) = -1 ENOENT (No such file or directory)<br \/>\nlstat(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/u.php\", {st_mode=S_IFREG|0744, st_size=113, ...}) = 0<br \/>\nlstat(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0<br \/>\nlstat(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0<br \/>\nlstat(\"\/home\/mvaldez\/SHARE\/DEV-www\", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0<br \/>\nlstat(\"\/home\/mvaldez\/SHARE\", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0<br \/>\nlstat(\"\/home\/mvaldez\", {st_mode=S_IFDIR|0711, st_size=4096, ...}) = 0<br \/>\nlstat(\"\/home\", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0<br \/>\nopen(\"\/home\/mvaldez\/SHARE\/DEV-www\/testfiles\/unlinktest\/u.php\", O_RDONLY) = 18<br \/>\nfstat(18, {st_mode=S_IFREG|0744, st_size=113, ...}) = 0<br \/>\nfstat(18, {st_mode=S_IFREG|0744, st_size=113, ...}) = 0<br \/>\nfstat(18, {st_mode=S_IFREG|0744, st_size=113, ...}) = 0<br \/>\nmmap(NULL, 113, PROT_READ, MAP_SHARED, 18, 0) = 0x7eff74391000<br \/>\nunlink(\"\/tmp\/eaccelerator\/4\/3\/eaccelerator-9032.9315914\") = -1 ENOENT (No such file or directory)<br \/>\nopen(\"\/tmp\/eaccelerator\/4\/3\/eaccelerator-9032.9315914\", O_WRONLY|O_CREAT|O_EXCL, 0600) = -1 ENOENT (No such file or directory)<br \/>\nwrite(2, \"EACCELERATOR: Open for write fail\"..., 117) = 117<br \/>\nwrite(2, \"EACCELERATOR cached: \\\"\/home\/mvald\"..., 78) = 78<br \/>\nmunmap(0x7eff74391000, 113)             = 0<br \/>\nclose(18)                               = 0<br \/>\n<strong>unlink(\"\/home\/mvaldez\/SHARE\/DEV-www\/eclipse\/inovman2old\/backups\/backup_20110801_100336_dump.txt.bz2\") = 0<\/strong><br \/>\nchdir(\"\/root\")                          = -1 EACCES (Permission denied)<br \/>\nrt_sigaction(SIGSEGV, {SIG_DFL, [SEGV], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, {0x7eff68225d60, [SEGV], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, 8) = 0<br \/>\nrt_sigaction(SIGFPE, {SIG_DFL, [FPE], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, {0x7eff68225d60, [FPE], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, 8) = 0<br \/>\nrt_sigaction(SIGBUS, {SIG_DFL, [BUS], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, {0x7eff68225d60, [BUS], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, 8) = 0<br \/>\nrt_sigaction(SIGILL, {SIG_DFL, [ILL], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, {0x7eff68225d60, [ILL], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, 8) = 0<br \/>\nrt_sigaction(SIGABRT, {SIG_DFL, [ABRT], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, {0x7eff68225d60, [ABRT], SA_RESTORER|SA_RESTART, 0x7eff71b6cf30}, 8) = 0<br \/>\nmunmap(0x7eff74392000, 528384)          = 0<br \/>\nopen(\"\/dev\/urandom\", O_RDONLY)          = 18<br \/>\nread(18, \"\\323\\342\\363\\30\\262\\277\\266\\4\"..., 8) = 8<br \/>\nclose(18)                               = 0<br \/>\nopen(\"\/dev\/urandom\", O_RDONLY)          = 18<br \/>\nread(18, \"X\\364]:\\33W\\27\\31\"..., 8)     = 8<br \/>\nclose(18)                               = 0<br \/>\nopen(\"\/dev\/urandom\", O_RDONLY)          = 18<br \/>\nread(18, \"\\245\\201\\317H\\204\\264\\374,\"..., 8) = 8<br \/>\nclose(18)                               = 0<br \/>\nsetitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0<br \/>\nwritev(17, [{\"HTTP\/1.1 200 OK\\r\\nDate: Mon, 01 Au\"..., 277}], 1) = 277<br \/>\nread(17, 0x207ddd8, 8000)               = -1 EAGAIN (Resource temporarily unavailable)<br \/>\nwrite(9, \"192.168.246.25 - - [01\/Aug\/2011:1\"..., 101) = 101<br \/>\nwrite(10, \"referer\\n\"..., 8)            = 8<br \/>\nwrite(11, \"agent\\n\"..., 6)              = 6<br \/>\nwrite(12, \"192.168.246.25 - - [01\/Aug\/2011:1\"..., 159) = 159<br \/>\npoll([{fd=17, events=POLLIN}], 1, 15000) =<\/code><\/p>\n<p>Success! Great, after 7 years I finally found out the cause of this.<\/p>\n<p>So now, the real fix is to make <em>libtrash<\/em> to load for regular users but not the <em>nobody<\/em> user (or root, as root is the one launching <em>rc.httpd<\/em> when booting).<\/p>\n<p><strong>Step 9:<\/strong> So, in <em>\/etc\/profile.d\/default.sh<\/em> I changed this:<\/p>\n<pre>export LD_PRELOAD=\/usr\/local\/lib\/libtrash.so<\/pre>\n<p>to this:<\/p>\n<pre>if [ $(\/bin\/id -g) -eq 100 ] ; then\r\n  export LD_PRELOAD=\/usr\/local\/lib\/libtrash.so\r\nfi<\/pre>\n<p>In this way only users from the group with GID 100 (regular users in this server) will have <em>libtrash<\/em> preloaded.<\/p>\n<p>The funny thing is: in the README file of <em>libtrash<\/em> there is note about this problem. I missed it because in the first libtrash version I used (2.3) there was not such a note. And I upgraded libtrash only when upgraded Slackware versions (2.8, then 3.2) by just recompiling and installing the latest version, didn&#8217;t pay too much attention to the latest notes in the README file.<\/p>\n<p>This is the note:<br \/>\n<em>IMPORTANT NOTE 3: If you are running a web (or other) server as user<br \/>\nnobody, then you should ensure that libtrash is not active for that<br \/>\nprocess. The issue is that by default libtrash refuses to remove files if<br \/>\nit will not be able to save them in that user&#8217;s trash can. The nobody<br \/>\naccount typically lacks a (writable) home directory; as such, when processes<br \/>\nrun as nobody try to remove a file, libtrash will always make that<br \/>\noperation fail. For that reason, always start servers run through the<br \/>\nnoboby account (or any other, low privileges account missing a writable<br \/>\nhome dir) with libtrash disabled (just prefix &#8220;LD_PRELOAD= &#8221; to the command<br \/>\nline). (My thanks to Nicola Fontana for pointing this out!)<\/em>\n<\/p>\n<p>Hope this help somebody else.<\/p>\n<p>Still, I cannot explain why this problem only happened sometimes, not always. I expected to <em>libtrash<\/em> to do its stuff (and fail) always. My theory is that when Slackware boots the root user who runs the rc.httpd script doesn&#8217;t have the LD_PRELOAD variable set, so libtrash is not intercepting for Apache; however, if I login into the server and restart Apache, my session has LD_PRELOAD set and now libtrash is intercepting all unlink calls from Apache\/PHP (however I didn&#8217;t check this).<\/p>\n<p>As a side note, you can see other interesting things in the strace output, like Apache checking every directory in the path for .htaccess files, or eaccelerator looking for a precompiled version of the script, etc. It makes me wonder if moving the web directory higher (closer to the file system root) would make Apache to serve pages faster.<\/p>\n<p>I learned today:<\/p>\n<ul>\n<li>When bulding your applications yourself, always read the relese notes when upgrading.<\/li>\n<li>It is easy to use strace to see what is going on inside PHP.<\/li>\n<li>Intercepting function calls of third party programs can have unexpected results (specially if something goes wrong).<\/li>\n<\/ul>\n<p>Sometimes I envy people with vanilla Linux setups&#8230; but only for a few seconds.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>How I fixed a PHP&#8217;s unlink function problem in my development server using strace to debug PHP&#8230; and why libtrash should not be used by the Apache user.<\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[12,9,7],"tags":[],"class_list":["post-124","post","type-post","status-publish","format-standard","hentry","category-in-english","category-open-source","category-software-development"],"_links":{"self":[{"href":"https:\/\/www.mariovaldez.net\/webapps\/blog\/wp-json\/wp\/v2\/posts\/124","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.mariovaldez.net\/webapps\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.mariovaldez.net\/webapps\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.mariovaldez.net\/webapps\/blog\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"https:\/\/www.mariovaldez.net\/webapps\/blog\/wp-json\/wp\/v2\/comments?post=124"}],"version-history":[{"count":17,"href":"https:\/\/www.mariovaldez.net\/webapps\/blog\/wp-json\/wp\/v2\/posts\/124\/revisions"}],"predecessor-version":[{"id":138,"href":"https:\/\/www.mariovaldez.net\/webapps\/blog\/wp-json\/wp\/v2\/posts\/124\/revisions\/138"}],"wp:attachment":[{"href":"https:\/\/www.mariovaldez.net\/webapps\/blog\/wp-json\/wp\/v2\/media?parent=124"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.mariovaldez.net\/webapps\/blog\/wp-json\/wp\/v2\/categories?post=124"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.mariovaldez.net\/webapps\/blog\/wp-json\/wp\/v2\/tags?post=124"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}