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!
