Note: Skip to "EDIT #2" for new info - I'll leave the original here, but it's less relevant now.
I need some troubleshooting help - it's infuriating when a system gives me no feedback, so I don't know what to look for.
I'm setting up a new server on Linode: CentOS7, nginx, and php-fpm. I also have a local VM whose configuration should be really similar. One piece of PHP code builds a file from database data, saves it in a tmp directory, and then runs a command on it (uplatex, which has a symlink in /usr/local/bin so all users should find it) to create additional files. On my VM it runs fine, but on the cloud server nothing happens that I can see - no error, no output. It also runs fine from the SSH command line, even if I do my best to simulate the situation of the failure. The only thing I can't simulate is going through nginx.
Here is the troubleshooting code I have gradually built up trying to get the system to give me some clues:
echo "<html><pre>"; echo "\nMy user (whoami): "; system('whoami'); echo "\nMy groups: "; system('groups'); echo "\nMy group right now (id -gn): "; system('id -gn'); echo "\nIs $tmppath writable [according to PHP itself, not system()/exec()]? "; echo is_writable($tmppath)?'Yes':'No'; echo "\nIs $tmppath writable [according to a script line in system()]? "; system("if [ -w $tmppath ] ; then echo 'Yes' ; else echo 'No' ; fi"); echo "\nI'll test writing a file - did it get created? "; echo system("cd $tmppath;cat \"test\" > dummy.txt"); echo is_file($tmppath.'dummy.txt')?'Yes':'No'; echo "\nWhat is the info about that file?\n"; system("ls -l ".$tmppath."dummy.txt"); echo "\nIs uplatex an executable command to me?\n"; system('command -v uplatex'); echo "\nCan I see the $fileroot.tex file?\n"; system("ls -l $tmppath$fileroot.*"); echo "\nI'm going to try 'cd $tmppath;uplatex $fileroot' now:\n"; system("cd $tmppath;uplatex $fileroot"); echo "Done. There should have been output above this line.\n"; echo "\nDid it create .dvi?\n"; system("ls -l $tmppath$fileroot.*"); echo "</pre><br>\n"; On Linode I get the following output:
My user (whoami): www-user My groups: www-data My group right now (id -gn): www-data Is /var/www/tmp/ writable [according to PHP itself, not system()/exec()]? Yes Is /var/www/tmp/ writable [according to a script line in system()]? Yes I'll test writing a file - did it get created? Yes What is the info about that file? -rw-r--r-- 1 www-user www-data 0 May 12 23:23 /var/www/tmp/dummy.txt Is uplatex an executable command to me? /usr/local/bin/uplatex Can I see the dev-karen-142318.tex file? -rw-r--r-- 1 www-user www-data 9286 May 12 23:23 /var/www/tmp/dev-karen-142318.tex I'm going to try 'cd /var/www/tmp/;uplatex dev-karen-142318' now: Done. There should have been output above this line. Did it create .dvi? -rw-r--r-- 1 www-user www-data 9286 May 12 23:23 /var/www/tmp/dev-karen-142318.tex On my VM, I get a bunch of output for the call to uplatex (I chopped out most of it for brevity), and the resulting files are just as they should be:
My user (whoami): www-user My groups: www-data My group right now (id -gn): www-data Is /var/www/tmp/ writable [according to PHP itself, not system()/exec()]? Yes Is /var/www/tmp/ writable [according to a script line in system()]? Yes I'll test writing a file - did it get created? Yes What is the info about that file? -rwxrwxr--. 1 www-data www-data 0 May 12 23:43 /var/www/tmp/dummy.txt Is uplatex an executable command to me? /usr/local/bin/uplatex Can I see the dev-dev-144353.tex file? -rwxrwxr--. 1 www-data www-data 1286 May 12 23:43 /var/www/tmp/dev-dev-144353.tex I'm going to try 'cd /var/www/tmp/;uplatex dev-dev-144353' now: This is e-upTeX, Version 3.14159265-p3.7-u1.21-160201-2.6 (utf8.uptex) (TeX Live 2016) (preloaded format=uplatex) restricted \write18 enabled. entering extended mode (./dev-dev-144353.tex pLaTeX2e <2016/11/29u01> (based on LaTeX2e <2016/03/31> patch level 3) ...yada yada... Output written on dev-dev-144353.dvi (1 page, 952 bytes). Transcript written on dev-dev-144353.log. Done. There should have been output above this line. Did it create .dvi? -rwxrwxr--. 1 www-data www-data 8 May 12 23:43 /var/www/tmp/dev-dev-144353.aux -rwxrwxr--. 1 www-data www-data 952 May 12 23:43 /var/www/tmp/dev-dev-144353.dvi -rwxrwxr--. 1 www-data www-data 12980 May 12 23:43 /var/www/tmp/dev-dev-144353.log -rwxrwxr--. 1 www-data www-data 1286 May 12 23:43 /var/www/tmp/dev-dev-144353.tex In SSH on the Linode server, this is the closest I could come to simulating the failure scenario (the only layer missing is the nginx engine), but it didn't fail:
[root](23:15:10)[/var/www/tmp]$ su www-user bash-4.2$ whoami www-user bash-4.2$ groups www-user www-data bash-4.2$ id -gn www-user bash-4.2$ ls -la total 20 drwxr-xr-x 2 www-user www-data 4096 May 12 23:23 . drwxrwxr-x 7 root www-data 4096 May 12 12:13 .. -rw-r--r-- 1 www-user www-data 9286 May 12 23:23 dev-karen-142318.tex -rw-r--r-- 1 www-user www-data 0 May 12 23:23 dummy.txt bash-4.2$ uplatex dev-karen-142318 This is e-upTeX, Version 3.14159265-p3.7-u1.21-160201-2.6 (utf8.uptex) (TeX Live 2016) (preloaded format=uplatex) restricted \write18 enabled. entering extended mode (./dev-karen-142318.tex pLaTeX2e <2016/11/29u01> (based on LaTeX2e <2017/01/01> patch level 3) ...yada yada... Output written on dev-karen-142318.dvi (10 pages, 5472 bytes). Transcript written on dev-karen-142318.log. bash-4.2$ ls -l total 40 -rw-r--r-- 1 www-user www-user 8 May 12 23:24 dev-karen-142318.aux -rw-r--r-- 1 www-user www-user 5472 May 12 23:24 dev-karen-142318.dvi -rw-r--r-- 1 www-user www-user 12767 May 12 23:24 dev-karen-142318.log -rw-r--r-- 1 www-user www-data 9286 May 12 23:23 dev-karen-142318.tex -rw-r--r-- 1 www-user www-data 0 May 12 23:23 dummy.txt bash-4.2$ I did notice some odd differences in users, groups, and permissions, but I can't imagine how it would matter. On my VM, although whoami says www-user, files created are owned by www-data (group also www-data). On Linode, if I'm running my code using the webserver, the user is www-user but the group is www-data. In SSH, after su www-user the group is also www-user. Also, on my VM the new files' permissions are 774, while on Linode they're 644 (I prefer 644, and that should be sufficient for this; I don't know why the VM is so liberal, but it's just a development machine, so I don't care). You can see all those things in the output above. But I can't find anything that would prevent uplatex from running or creating files, and if there was a permissions or access problem, I would have expected an error message - uplatex is normally quite gregarious.
Does anyone have suggestions for what to check? This Serverfault thread sounded promising, but I don't see how the accepted answer could relate to me. Is there some sort of secret security setting on Linode that doesn't like typesetters run through webservers? ;-)
EDIT to answer questions in comments... SELinux is disabled, and here is the output of env:
XDG_SESSION_ID=5654 HOSTNAME=puphpet2 TERM=xterm SHELL=/bin/bash HISTSIZE=1000 SSH_CLIENT=182.165.72.24 58682 22 OLDPWD=/root SSH_TTY=/dev/pts/1 USER=root LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=01;05;37;41:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.jpg=01;35:*.jpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.axv=01;35:*.anx=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=01;36:*.au=01;36:*.flac=01;36:*.mid=01;36:*.midi=01;36:*.mka=01;36:*.mp3=01;36:*.mpc=01;36:*.ogg=01;36:*.ra=01;36:*.wav=01;36:*.axa=01;36:*.oga=01;36:*.spx=01;36:*.xspf=01;36: MAIL=/var/spool/mail/root PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/opt/puppetlabs/bin:/root/bin PWD=/var/www/tmp LANG=en_US.UTF-8 HISTCONTROL=ignoredups SHLVL=1 HOME=/root LOGNAME=root SSH_CONNECTION=182.165.72.24 58682 139.162.99.170 22 LESSOPEN=||/usr/bin/lesspipe.sh %s XDG_RUNTIME_DIR=/run/user/0 _=/usr/bin/env EDIT #2: New Information! I just discovered that the shell was sending errors to stderr, while I was only looking at stdout. I used 2>&1 to redirect it, and this error appeared:
lstat(./euptex) failed ... ./euptex: No such file or directory euptex: ../../../texk/kpathsea/progname.c:316: remove_dots: Assertion `ret' failed. But using the exact same scenario of PHP's system() function (so the user, shell, etc. is all the same) to test for different things I can think of, I get these results:
echo $PATH /usr/local/bin:/usr/bin ls -l /usr/local/bin/euptex lrwxrwxrwx 1 root root 47 May 12 18:30 /usr/local/bin/euptex -> /usr/local/texlive/2016/bin/x86_64-linux/euptex whereis euptex euptex: /usr/local/bin/euptex ls -l /usr/local/texlive/2016/bin/x86_64-linux/euptex -rwxr-xr-x 1 root root 592016 May 10 2016 /usr/local/texlive/2016/bin/x86_64-linux/euptex euptex --help 2>&1 lstat(./euptex) failed ... ./euptex: No such file or directory euptex: ../../../texk/kpathsea/progname.c:316: remove_dots: Assertion `ret' failed. If it's in the path, and whereis can see it, and the link points to a real file, why is the shell having so much trouble? And there is no file called progname.c on my entire server, so I have no idea why it's talking about line 316 in it. I'm way out of my league!
envcommand above.