Page MenuHomePhabricator
Create Task
Maniphest T225966

Toolforge: File upload to PHP webservice fails because temp file can't be opened
Closed, DuplicatePublic
Actions

Description

Sometimes when I try to upload a file using PHP sometimes I get a Internal Server error. The error log then shows:2019-06-17 18:21:24: (chunk.c.553) opening temp-file failed: No such file or directory. Restarting the webservice solves this issue.
Project: Wikiportretdev
Server: tools-sgebastion-07
service.manifest:

backend: gridengine
distribution: debian
version: 3
web: lighttpd

The problem isn't in the code of the application, because the live server (not WMF hosted) never gives this issue.

Related Objects

Event Timeline

Mbch331 created this task.Jun 17 2019, 6:31 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJun 17 2019, 6:31 PM
Mbch331 mentioned this in T217815: Grid Engine lighttpd error "opening temp-file failed: No such file or directory".Jun 18 2019, 8:59 PM
MusikAnimal subscribed.Jun 19 2019, 1:47 AM

We had this problem with SVG Translate T217815: Grid Engine lighttpd error "opening temp-file failed: No such file or directory", which uploads files too.

However I also had this problem with https://tools.wmflabs.org/global-search/ which has no uploads of any sort. There is some caching on the file system, maybe that's it.

zhuyifei1999 subscribed.Jun 19 2019, 7:11 AM

What is the path that is being created / opened?

Mbch331 added a comment.Jun 19 2019, 7:54 AM

The file i'm trying to access is $_FILES['file']['tmp_name']. The code uses the default path settings provided by the webserver.

Mbch331 added a comment.EditedJun 19 2019, 5:01 PM

Just did some debugging and the issue already occurs on upload (just normal file upload via form POST). I tried to var_dump($_FILES);die(); and it already gives a Internal Server error before I even do anything else with the file.
All the error log says is:
2019-06-19 16:57:51: (chunk.c.553) opening temp-file failed: No such file or directory
2019-06-19 16:58:42: (chunk.c.553) opening temp-file failed: No such file or directory

zhuyifei1999 added a comment.Jun 19 2019, 5:26 PM
In T225966#5269162, @Mbch331 wrote:

Just did some debugging and the issue already occurs on upload (just normal file upload via form POST). I tried to var_dump($_FILES);die(); and it already gives a Internal Server error before I even do anything else with the file.
All the error log says is:
2019-06-19 16:57:51: (chunk.c.553) opening temp-file failed: No such file or directory
2019-06-19 16:58:42: (chunk.c.553) opening temp-file failed: No such file or directory

05:20:47 0 ✓ zhuyifei1999@tools-sgewebgrid-lighttpd-0927: ~$ ps uf -u tools.wikiportretdev
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
tools.w+ 27118  0.0  0.0  61412  6232 ?        Ss   Jun11   1:29 /usr/sbin/lighttpd -f /var/run/lighttpd/wikiportretdev -D
tools.w+ 27122  0.0  0.4 525728 34272 ?        Ss   Jun11   0:00  \_ /usr/bin/php-cgi
tools.w+ 27123  0.0  0.0 525728  7032 ?        S    Jun11   0:00  |   \_ /usr/bin/php-cgi
tools.w+ 27124  0.0  0.0 525728  7032 ?        S    Jun11   0:00  |   \_ /usr/bin/php-cgi
tools.w+ 27125  0.0  0.4 525728 34296 ?        Ss   Jun11   0:00  \_ /usr/bin/php-cgi
tools.w+ 27126  0.0  0.4 566376 40092 ?        S    Jun11   0:02      \_ /usr/bin/php-cgi
tools.w+ 27127  0.0  0.3 552076 26008 ?        S    Jun11   0:00      \_ /usr/bin/php-cgi
05:21:08 0 ✓ zhuyifei1999@tools-sgewebgrid-lighttpd-0927: ~$ sudo lsof -p 27118 | tail
lighttpd 27118 tools.wikiportretdev  mem       REG    254,3    26872  1181611 /usr/lib/lighttpd/mod_dirlisting.so
lighttpd 27118 tools.wikiportretdev  mem       REG    254,3    10080  1181628 /usr/lib/lighttpd/mod_staticfile.so
lighttpd 27118 tools.wikiportretdev    0u      CHR      1,3      0t0     1028 /dev/null
lighttpd 27118 tools.wikiportretdev    1u      CHR      1,3      0t0     1028 /dev/null
lighttpd 27118 tools.wikiportretdev    2w      REG     0,47    58024 80154233 /mnt/nfs/labstore-secondary-tools-project/wikiportretdev/error.log (nfs-tools-project.svc.eqiad.wmnet:/project/tools/project)
lighttpd 27118 tools.wikiportretdev    3w      REG     0,19        6 76353791 /run/lighttpd/wikiportretdev.pid
lighttpd 27118 tools.wikiportretdev    4u     IPv4 76353792      0t0      TCP *:53949 (LISTEN)
lighttpd 27118 tools.wikiportretdev    5w      REG     0,47    58024 80154233 /mnt/nfs/labstore-secondary-tools-project/wikiportretdev/error.log (nfs-tools-project.svc.eqiad.wmnet:/project/tools/project)
lighttpd 27118 tools.wikiportretdev    6w      REG     0,47   531412 80202134 /mnt/nfs/labstore-secondary-tools-project/wikiportretdev/access.log (nfs-tools-project.svc.eqiad.wmnet:/project/tools/project)
lighttpd 27118 tools.wikiportretdev    7u  a_inode     0,11        0     7543 [eventpoll]
05:21:14 0 ✓ zhuyifei1999@tools-sgewebgrid-lighttpd-0927: ~$ sudo lsof -p 27122 | tail
php-cgi 27122 tools.wikiportretdev  mem    REG              254,3   256144   929561 /usr/lib/x86_64-linux-gnu/libxslt.so.1.1.29
php-cgi 27122 tools.wikiportretdev  mem    REG              254,3    59720  1182132 /usr/lib/php/20170718/zip.so
php-cgi 27122 tools.wikiportretdev  mem    REG              254,3   101648   919254 /usr/lib/x86_64-linux-gnu/libzip.so.4.0
php-cgi 27122 tools.wikiportretdev  mem    REG              254,3    14944  1182064 /usr/lib/php/20170718/apc.so
php-cgi 27122 tools.wikiportretdev  DEL    REG                0,5          76353046 /dev/zero
php-cgi 27122 tools.wikiportretdev  DEL    REG                0,5          76353051 /dev/zero
php-cgi 27122 tools.wikiportretdev    0u  unix 0xffff9560c13cb000      0t0 76353794 /var/run/lighttpd/php.socket.wikiportretdev-0 type=STREAM
php-cgi 27122 tools.wikiportretdev    1u   CHR                1,3      0t0     1028 /dev/null
php-cgi 27122 tools.wikiportretdev    2w   REG               0,47    58024 80154233 /mnt/nfs/labstore-secondary-tools-project/wikiportretdev/error.log (nfs-tools-project.svc.eqiad.wmnet:/project/tools/project)
php-cgi 27122 tools.wikiportretdev    3u   REG              253,0        0       15 /tmp/.ZendSem.aI1Lqg (deleted)
05:21:26 0 ✓ zhuyifei1999@tools-sgewebgrid-lighttpd-0927: ~$ sudo lsof -p 27123 | tail
php-cgi 27123 tools.wikiportretdev  mem    REG              254,3   256144   929561 /usr/lib/x86_64-linux-gnu/libxslt.so.1.1.29
php-cgi 27123 tools.wikiportretdev  mem    REG              254,3    59720  1182132 /usr/lib/php/20170718/zip.so
php-cgi 27123 tools.wikiportretdev  mem    REG              254,3   101648   919254 /usr/lib/x86_64-linux-gnu/libzip.so.4.0
php-cgi 27123 tools.wikiportretdev  mem    REG              254,3    14944  1182064 /usr/lib/php/20170718/apc.so
php-cgi 27123 tools.wikiportretdev  DEL    REG                0,5          76353046 /dev/zero
php-cgi 27123 tools.wikiportretdev  DEL    REG                0,5          76353051 /dev/zero
php-cgi 27123 tools.wikiportretdev    0u  unix 0xffff9560c13cb000      0t0 76353794 /var/run/lighttpd/php.socket.wikiportretdev-0 type=STREAM
php-cgi 27123 tools.wikiportretdev    1u   CHR                1,3      0t0     1028 /dev/null
php-cgi 27123 tools.wikiportretdev    2w   REG               0,47    58024 80154233 /mnt/nfs/labstore-secondary-tools-project/wikiportretdev/error.log (nfs-tools-project.svc.eqiad.wmnet:/project/tools/project)
php-cgi 27123 tools.wikiportretdev    3u   REG              253,0        0       15 /tmp/.ZendSem.aI1Lqg (deleted)
05:21:30 0 ✓ zhuyifei1999@tools-sgewebgrid-lighttpd-0927: ~$ sudo stat /proc/27123/fd/3
  File: /proc/27123/fd/3 -> /tmp/.ZendSem.aI1Lqg (deleted)
  Size: 64        	Blocks: 0          IO Block: 1024   symbolic link
Device: 4h/4d	Inode: 76389246    Links: 1
Access: (0700/lrwx------)  Uid: (53967/tools.wikiportretdev)   Gid: (53967/tools.wikiportretdev)
Access: 2019-06-19 02:52:02.177299010 +0000
Modify: 2019-06-11 06:23:02.185537160 +0000
Change: 2019-06-11 06:23:02.185537160 +0000
 Birth: -
05:21:40 0 ✓ zhuyifei1999@tools-sgewebgrid-lighttpd-0927: ~$ sudo stat -L /proc/27123/fd/3
  File: /proc/27123/fd/3
  Size: 0         	Blocks: 0          IO Block: 4096   regular empty file
Device: fd00h/64768d	Inode: 15          Links: 0
Access: (0666/-rw-rw-rw-)  Uid: (53967/tools.wikiportretdev)   Gid: (53967/tools.wikiportretdev)
Access: 2019-06-19 17:20:28.276009770 +0000
Modify: 2019-06-11 05:48:26.619171723 +0000
Change: 2019-06-11 05:48:26.619171723 +0000
 Birth: -

I see an empty file named /tmp/.ZendSem.aI1Lqg that has been deleted but still attached to fd3. A deleted directory makes more sense though, since the error is from opening a new fd afaict.

In any case, I have attached strace to the 6 PHP processes. @Mbch331 mind trying another upload and I'll see if I can spot the exact file that is being created / accesses that causes this error.

zhuyifei1999 renamed this task from WMFLabs: File upload fails because temp file can't be opened to Toolforge: File upload to PHP webservice fails because temp file can't be opened.Jun 19 2019, 5:29 PM
Mbch331 added a comment.Jun 19 2019, 5:41 PM

Just attempted to upload a file.

zhuyifei1999 added a comment.Jun 19 2019, 5:46 PM

Did not get anything on the 4 PHPs. I just attached to lighttpd as well. Mind doing it again? Just to confirm, the tool is wikiportretdev right?

Mbch331 added a comment.Jun 19 2019, 5:48 PM

Yes, this is the correct tool and just tried another upload.

zhuyifei1999 added a comment.Jun 19 2019, 5:55 PM

Hmm, that flood of read() syscalls flooded my scrollback (I'm using screen). Would you try a smaller file? This is what it ended with (the file never reached PHP it seems):

373fV-\214\256\265\254!MR@\217\333\234\232O\227YOkk\7\273\357\216_Ll\n\300\232;b\310-"..., 4096) = 3000
[pid 27118] read(8, "", 4096)           = 0
[pid 27118] close(8)                    = 0
[pid 27118] accept4(4, 0x7ffcbd0539f0, [112], SOCK_CLOEXEC|SOCK_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)
[pid 27118] open("/proc/loadavg", O_RDONLY) = 8
[pid 27118] read(8, "0.00 0.00 0.01 2/206 26797\n", 64) = 27

(syscalls wait4 & epoll_wait are muted because they are way too noisy)

Mbch331 added a comment.Jun 19 2019, 6:06 PM

Smaller image went through. I'll stick with smaller images. The image size isn't important for testing the changes. And it's not a live tool.

zhuyifei1999 added a comment.Jun 19 2019, 6:21 PM
[pid 27118] write(6, "172.16.6.39 tools.wmflabs.org - [19/Jun/2019:18:02:30 +0000] \"POST /wikiportretdev/upload.php HTTP/1.1\" 302 7506 \"https://tools."..., 248) = 248

Hmm... I could try mute the read syscall to see what is going on with larger files but that might lose information.

Mbch331 added a comment.Jun 19 2019, 7:12 PM

File that results in a 500 error is a 1,61 MB JPG file
File that results in a working upload is a 62,3 kB JPG file

MusikAnimal added a comment.Jun 19 2019, 8:23 PM

This just happened again for Global Search, T225587. I question if this has anything to do with uploads, or just the file system in general?

MusikAnimal mentioned this in T225587: Search results page stops loading midway.Jun 19 2019, 8:24 PM
MusikAnimal mentioned this in T225686: Load issue with pdfs .Jun 20 2019, 5:55 PM
Mbch331 added a comment.Jul 2 2019, 7:45 PM

Issue occurred again today. Don't know the size of the image as someone else uploaded the image as he was testing the tool

bd808 closed this task as a duplicate of T217815: Grid Engine lighttpd error "opening temp-file failed: No such file or directory".Oct 16 2019, 2:55 AM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL