vmware(CentOS7)上にインストールしたapache+php環境で、ログ出力がされない件

Question

お世話になっております。

自力で調べたのですが、どうしても解決できない為、
下記の質問させていただきます。

■環境
vmware(CentOS7)
apache2 (手作業でインストール)
php5.3
作業マシンはwindows7

■症状
vmware上で実行されるphpから、ログ出力をしてみようと思い
下記のようなコードを書きましたが、どこにもログ出力されている形跡がなく、原因が不明です。

<?php
echo "aaa<br>";
error_log("test \n", "3", "/tmp/a.log");
error_log("test2 \n", "3", "/var/www/a.log");
error_log("test3 \n", "3", "/var/www/html/a.log");
echo "bbb<br>";
?>

■補足
・php.iniや、apacheの設定をみましたが、特に書き換えた箇所はなく、デフォルトの状態です。

・phpでechoした文字列(aaaやbbb)はブラウザから見えるので、apacheとphpの基本的なインストールは完了しています。

・php.iniでエラーログ(php_error.log)を出力する設定をしても、正しく出力されませんでした。

・同様にerror_log関数を使ったファイル出力も、正しく出力されていません(画面上で特にエラーが出るわけでもない)

・上記の現象から、apache経由でファイルを書き込む際の権限周りが原因のようですが、もしそうだとしてもどこをどう調整すればいいのかがわかりません。

■期待する動作
・error_log関数で文字列を出力したい

・php_error.logで文字列を出力したい

以上になります。
どうぞよろしくお願い致します。

(追記)
補足です。
出力しようとした文字列は、ファイルすら作られていない状況です。

Answer 1

SELinuxで禁止されているのでは？
getenforce
というコマンドで、
Enforcing
という結果であれば、
setenforce 0
で一時的に無効にして確認してみてください。
それが原因であれば、どうするかについては、SELinuxについて調べてみてください。

試行錯誤した部分は、元に戻しておいた方が良いでしょうね。

Comments

[退会済みユーザー]

otnさま

回答ありがとうございます。

その後、上記の方法で試してみたところ、問題なくログ出力ができ、
開発を進めることができました。

もともとvmware上での開発で、外部のサーバとやりとりすることも
ない為、しばらくはsetenforceを無効にするやり方で使おうと思います。

他のディストリビューションでは問題なかったので、ソースを疑って
ましたが、OS側に原因があったとは勉強になりました。

ありがとうございました。

Answer 2

<?php
ini_set('display_errors', 1);
error_reporting(E_ALL);

echo "aaa<br>";
error_log("test \n", "3", "/tmp/a.log");
error_log("test2 \n", "3", "/var/www/a.log");
error_log("test3 \n", "3", "/var/www/html/a.log");
echo "bbb<br>";

上記の現象から、apache経由でファイルを書き込む際の権限周りが原因のようですが、もしそうだとしてもどこをどう調整すればいいのかがわかりません。

まずは、推測ではなく、上記のコードを実行すれば、エラーメッセージがディスプレイに表示されます。

Comments

[退会済みユーザー]

Kosuke_Shibuya さま

回答ありがとうございます。

ディスプレイ表示させたところ、下記のエラーメッセージが表示されました。

Warning: error_log(/var/www/a.log): failed to open stream: Permission denied in /var/www/html/test.php on line 10

権限がおかしいらしいですが、ディレクトリの所有者権限を「apache.apache」や「root.root」にしたり、パーミッションを全開の「777」にしてみたりもしましたが、どうやってもエラーになります。

引き続き調べていますが、、解決の糸口がつかめず。です。
以上になります。

[退会済みユーザー]

具体的にどんなコマンドを打ったのですか？
ファイルの所有者、グループの変更が正しくなされたかをどんなコマンドで確認しましたか？
コマンドが間違っている可能性すらあるので、その情報を正しいものとして回答はできません。

apache.apache と書いている時点でコマンドの間違いの匂いがしていますが…

[退会済みユーザー]

Kosuke_Shibuya さま

回答ありがとうございます。

コマンドは以下のように打ちました。

cd /var/www/
chown root.root html
chmod 777 html

htmlディレクトリ直下にtest.phpを設置して、ブラウザでアクセス。
という具合です。

同様にroot以外の権限も試しました
chown apache.apache html
のように試しましたが、状況変わらず。でした。

以上になります。
apacheそのものの設定がミスっているのかと勘ぐってしまっています。。

[退会済みユーザー]

補足

chwon root.root test.php

等、phpファイルの所有者権限も変更し、パーミッションを全開(777)にもしてみました。(結果同様です)

[退会済みユーザー]

コマンドが間違っています。
ls -al /var/www 確認
chown apache:apache /var/www　変更
ls -al /var/www 確認

[退会済みユーザー]

回答ありがとうございます。

ためしてみましたが、権限エラーは変わらずでした。

ちなみに、教えていただいたコマンドで所有者権限を変えましたが、
それぞれのディレクトリとphpファイルは以下のような権限になっています。

drwxrwxrwx. 21 apache apache 4096 Jan 14 09:53 var
drwxrwxrwx. 4 apache apache 31 Sep 8 08:35 www
drwxrwxrwx. 12 apache apache 4096 Jan 14 09:33 html
-rwxrwxr-x. 1 apache apache 299 Jan 14 10:36 test.php

お恥ずかしい話、全て全開にしてしまっています。
最初の「/var」はroot root でいいのかもしれません。

[退会済みユーザー]

上記の状態で

/var/www/html/test.php

にブラウザからアクセスしています。

http://192.168.xxx.xxx/test.php

という、シンプルなものです。

phpの中身は下記のようなシンプルなものです。

<?php

ini_set('display_errors', 1);
error_reporting(E_ALL);

echo "aaa<br>";

error_log("test0 \n", "3", "/var/www/html/a.log");
error_log("test1 \n", "3", "/tmp/a.log");
error_log("test2 \n", "3", "/var/www/a.log");

echo "bbb 2<br>";

?>

[退会済みユーザー]

http://php.net/manual/ja/function.error-log.php

error_log("test2", 3, "/var/www/a.log");

で試してください

[退会済みユーザー]

ありがとうございます。

試した結果

Warning: error_log(/var/www/a.log): failed to open stream: Permission denied in /var/www/html/test.php on line 9

でした。

[退会済みユーザー]

ちなみにphpはこれ以上シンプルにできないレベルです･･･。

<?php

ini_set('display_errors', 1);
error_reporting(E_ALL);

echo "aaa<br>";

error_log("test2", 3, "/var/www/a.log");

echo "bbb 2<br>";

?>

[退会済みユーザー]

3についてる、"" は外しましたか？

[退会済みユーザー]

はい。

ダブルクォートは、はずしております。

[退会済みユーザー]

ここまでくると、apacheかphp.ini等のセッティングに問題があるのかどうか・・・という部分を疑っていますが、他のvmware(debian)等ではほぼデフォルトのままで、動作はしているので、どうゆうアプローチで調べていいのかが悩ましいところです。

[退会済みユーザー]

<?php

ini_set('display_errors', 1);
error_reporting(E_ALL);
touch('/var/www/a.log');
?>

を試してみてください。

[退会済みユーザー]

Warning: touch(): Unable to create file /var/www/a.log because Permission denied in /var/www/html/test.php on line 5

でした。

touchもできないとは･･･愕然としております。

[退会済みユーザー]

ls -al /var/www/

の結果を省略せずに補足してください。

[退会済みユーザー]

はい。ありがとうございます。

ls -al /var/www/と打ち込んだところ、以下のように出力されました。(全てです)

[root@localhost html]# ls -al /var/www/
total 8
drwxrwxrwx. 4 apache apache 31 Sep 8 08:35 .
drwxrwxrwx. 21 apache apache 4096 Jan 14 09:53 ..
drwxr-xr-x. 2 apache apache 6 Aug 25 03:12 cgi-bin
drwxrwxrwx. 12 apache apache 4096 Jan 14 09:33 html

[退会済みユーザー]

補足です。

cgi-binはディレクトリ表記でしたが、

cd cgi-binで中に入ると、なにもありませんでした。

[退会済みユーザー]

cat /etc/httpd/conf/httpd.conf | grep User

の結果を補足してください。

[退会済みユーザー]

はい。

[root@localhost html]# cat /etc/httpd/conf/httpd.conf | grep User
# User/Group: The name (or #number) of the user/group to run httpd as.
User apache
LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %I %O" combinedio
[root@localhost html]#

でした。
これは一体・・・。

[退会済みユーザー]

apache の実行ユーザーを確認するだけです。
必要な情報は　User apache

[退会済みユーザー]

はい。。

[退会済みユーザー]

コマンドで手動でファイルを作成した時にどうなるかを確認しましょう。

ターミナルで

touch /var/www/a.log
chown apache:apache /var/www/a.log
ls -al /var/www/a.log

ファイルができたのを確認したら、

<?php
ini_set('display_errors', 1);
error_reporting(E_ALL);
error_log("test2", 3, "/var/www/a.log");
?>

を実行します。

[退会済みユーザー]

phpからtouchができていない。ということは、ログの関数うんぬんの前の段階で
問題なような気がしてきました。

単純なファイル出力を試してみようと思います。

[退会済みユーザー]

なるほどです。

以下のコマンドを実行して、手動でファイルを作成し、

[root@localhost www]# chown apache:apache /var/www/a.log
[root@localhost www]# ls -al
total 8
drwxrwxrwx. 4 apache apache 43 Jan 14 11:18 .
drwxrwxrwx. 21 apache apache 4096 Jan 14 09:53 ..
-rw-r--r--. 1 apache apache 0 Jan 14 11:18 a.log
drwxr-xr-x. 2 apache apache 6 Aug 25 03:12 cgi-bin
drwxrwxrwx. 12 apache apache 4096 Jan 14 09:33 html
[root@localhost www]# ls -al /var/www/a.log
-rw-r--r--. 1 apache apache 0 Jan 14 11:18 /var/www/a.log
[root@localhost www]#

この後、ブラウザでアクセスしたみたところ

Warning: touch(): Utime failed: Permission denied in /var/www/html/test.php on line 5

でした。

[退会済みユーザー]

補足です。

「line 5」は2行目に空行があった為、実際には4行目の

error_log("test2", 3, "/var/www/a.log");

の行でエラーになっています。

[退会済みユーザー]

どうもPHP の実行ユーザーが apache ではなさそうですね。

[退会済みユーザー]

はい。

･･･サーバのセッティングの問題の気がしてきました。

[退会済みユーザー]

試しに、他のvmware(debiain)で

<?php
ini_set('display_errors', 1);
error_reporting(E_ALL);
error_log("test2", 3, "/var/www/a.log");
?>

を試したところ、サクっと動作してファイルが作成されましたので、、、

となると、CentOS7のapacheの入れ方というかセッティングの仕方がまずかったようです。

[退会済みユーザー]

> CentOS7のapacheの入れ方というかセッティングの仕方がまずかったようです。
一からやり直すのは面倒でしょ？だから協力しているわけで…

<?php
ini_set('display_errors', 1);
error_reporting(E_ALL);
echo exec('whoami');
?>

これを実行してください。

[退会済みユーザー]

ありがとうございます。そうですね。。

実行した結果

apache

と表示されました。
あれ・・・?

[退会済みユーザー]

おやおや、本当にあれっ？？？ですね。
apache とかソースビルドでインストールしたんでしょうか？

[退会済みユーザー]

インストール時のメモを確認しましたが、以下のようにしました。

# yum install -y httpd
# systemctl status httpd
# ss -nat
# systemctl start httpd.service
# systemctl status httpd.service

[退会済みユーザー]

問題なさそうですねー

[退会済みユーザー]

実行した結果↓のような表示になり、

httpd.service - The Apache HTTP Server
Loaded: loaded (/usr/lib/systemd/system/httpd.service; disabled)
Active: active (running) since Wed 2015-09-09 11:12:20 JST; 54min ago
Main PID: 3288 (httpd)
Status: "Total requests: 0; Current requests/sec: 0; Current traffic: 0 B/sec"
CGroup: /system.slice/httpd.service
|-3288 /usr/sbin/httpd -DFOREGROUND
|-3289 /usr/sbin/httpd -DFOREGROUND
|-3290 /usr/sbin/httpd -DFOREGROUND
|-3291 /usr/sbin/httpd -DFOREGROUND
|-3292 /usr/sbin/httpd -DFOREGROUND
`-3293 /usr/sbin/httpd -DFOREGROUND

Sep 09 11:12:19 localhost.localdomain httpd[3288]: AH00558: httpd: Could not reliably determine the server's full...sage
Sep 09 11:12:20 localhost.localdomain systemd[1]: Started The Apache HTTP Server.
Hint: Some lines were ellipsized, use -l to show in full.

[退会済みユーザー]

最終的には、下記のような操作をしまして

# ss -nat
iptablesを確認する
# iptables -L
サービスを落とす まずは確認
# systemctl status firewalld
落とす
# systemctl stop firewalld
再度、確認
# systemctl status firewalld
iptables を確認する
# iptables -L
自動起動サービスに登録する。
# chkconfig --list
試しに、サービスを探す
# systemctl list-unit-files | grep httpd
httpdを無効(enable)にする
# systemctl enable httpd.service
もう一度、確認する
# systemctl list-unit-files | grep httpd
ファイアウォールを無効にする
# systemctl list-unit-files | grep firewall
# systemctl disable firewalld.service
再度、確認して無効(disabled)になっていればOK
# systemctl list-unit-files | grep firewall
(CentOS7でのapacheの起動、停止、再起動)
# systemctl start httpd.service
# systemctl stop httpd.service
# systemctl restart httpd.service

結果、ブラウザでアクセス可能になりました。

[退会済みユーザー]

設定も問題なさそうなんですけどね。

httpd.conf の

ErrorLog logs/error_log
↓
ErrorLog /var/www/a.log

に変更して、httpd をリスタートすれば、利用可能になるとは思います。

[退会済みユーザー]

書き換えてhttpdリスタートしたらブラウザからアクセス不能になりました…。

なおかつsshもダメになってしまった。

vmware上で直接コマンド操作して、戻しています。
/etc/http/conf/httpd.conf

を編集しましたが、間違っているでしょうか。

[退会済みユーザー]

自己解決しそうです。

ErrorLog /var/www/a.log
↓
ErrorLog "/var/www/a.log"

に修正しました。

[退会済みユーザー]

どうやら

ErrorLog "/var/www/a.log"

の記述そのものはNGなようでした。「a.log」のファイルの有無に限らず
httpdの再起動後、ブラウザアクセスが不能になるようです(おそらく400を返している)

[退会済みユーザー]

リスタートした時に何かエラー出てませんでした？

[退会済みユーザー]

"" が余計でしたね。

ErrorLog /var/www/a.log

[退会済みユーザー]

リスタート時には下記メッセージが出ます。

[root@localhost httpd]# systemctl restart httpd.service
Job for httpd.service failed. See 'systemctl status httpd.service' and 'journalctl -xn' for details.

[退会済みユーザー]

↑

「""」はナシでやった結果です。

[退会済みユーザー]

結局

ErrorLog "logs/error_log"

に戻してリスタートすると、エラーが表示されませんでしたので、
今はそれに戻しました。

[退会済みユーザー]

systemctl status httpd.service

と

journalctl -xn

を実行してみましょうか

戻しちゃったらやっても意味ないか…

[退会済みユーザー]

ありがとうございます。

まずは1つ目は以下になりました。

[root@localhost httpd]# systemctl status httpd.service
httpd.service - The Apache HTTP Server
Loaded: loaded (/usr/lib/systemd/system/httpd.service; enabled)
Active: active (running) since Thu 2016-01-14 12:01:36 JST; 4min 0s ago
Process: 2527 ExecStop=/bin/kill -WINCH ${MAINPID} (code=exited, status=1/FAILURE)
Main PID: 2554 (httpd)
Status: "Total requests: 2; Current requests/sec: 0; Current traffic: 0 B/sec"
CGroup: /system.slice/httpd.service
|-2554 /usr/sbin/httpd -DFOREGROUND
|-2555 /usr/sbin/httpd -DFOREGROUND
|-2556 /usr/sbin/httpd -DFOREGROUND
|-2557 /usr/sbin/httpd -DFOREGROUND
|-2558 /usr/sbin/httpd -DFOREGROUND
|-2559 /usr/sbin/httpd -DFOREGROUND
`-2563 /usr/sbin/httpd -DFOREGROUND

Jan 14 12:01:36 localhost.localdomain systemd[1]: Starting The Apache HTTP Server...
Jan 14 12:01:36 localhost.localdomain httpd[2554]: AH00558: httpd: Could not reliably determine the server's full...sage
Jan 14 12:01:36 localhost.localdomain systemd[1]: Started The Apache HTTP Server.
Hint: Some lines were ellipsized, use -l to show in full.

[退会済みユーザー]

2つ目は↓です。（長くてすみませんが･･･)

[root@localhost httpd]# journalctl -xn
-- Logs begin at Thu 2016-01-14 11:54:26 JST, end at Thu 2016-01-14 12:01:36 JST. --
Jan 14 12:01:01 localhost.localdomain systemd[1]: Starting Session 4 of user root.
-- Subject: Unit session-4.scope has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit session-4.scope has begun starting up.
Jan 14 12:01:01 localhost.localdomain systemd[1]: Started Session 4 of user root.
-- Subject: Unit session-4.scope has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit session-4.scope has finished starting up.
--
-- The start-up result is done.
Jan 14 12:01:01 localhost.localdomain CROND[2534]: (root) CMD (run-parts /etc/cron.hourly)
Jan 14 12:01:01 localhost.localdomain run-parts(/etc/cron.hourly)[2537]: starting 0anacron
Jan 14 12:01:02 localhost.localdomain run-parts(/etc/cron.hourly)[2543]: finished 0anacron
Jan 14 12:01:02 localhost.localdomain run-parts(/etc/cron.hourly)[2545]: starting 0yum-hourly.cron
Jan 14 12:01:02 localhost.localdomain run-parts(/etc/cron.hourly)[2549]: finished 0yum-hourly.cron
Jan 14 12:01:36 localhost.localdomain systemd[1]: Starting The Apache HTTP Server...
-- Subject: Unit httpd.service has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit httpd.service has begun starting up.
Jan 14 12:01:36 localhost.localdomain httpd[2554]: AH00558: httpd: Could not reliably determine the server's fully quali
Jan 14 12:01:36 localhost.localdomain systemd[1]: Started The Apache HTTP Server.
-- Subject: Unit httpd.service has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit httpd.service has finished starting up.
--
-- The start-up result is done.

[退会済みユーザー]

↑ちなみにErrorLogは戻してしまってます･･･。

[退会済みユーザー]

ErrorLog "logs/error_log"
に戻した後の結果ですよね

[退会済みユーザー]

↑はい。そうです。

[退会済みユーザー]

httpdで

AH00558: httpd: Could not reliably determine the server's full...sage

と言われ、journalctlで

AH00558: httpd: Could not reliably determine the server's fully quali

と言われている点が、もしかしてエラーになっているのでしょうか。
引き続き調査したいところですが、そろそろ限界が･･･

また時間をおいて、調査させていただこうと思います。
ひとまずありがとうございました。

[退会済みユーザー]

<?php
ini_set('display_errors', 1);
error_reporting(E_ALL);
error_log("test2", 0);
?>

を実行した結果、

/var/log/error_log に test2 か書き込まれているかを確認してみましょうか。

cat /var/log/error_log | grep test2

[退会済みユーザー]

エラーログそのものが出力されなかったです。

[root@localhost ~]# cat /var/log/error_log | grep test2
cat: /var/log/error_log: No such file or directory

[退会済みユーザー]

パスが間違ってました
/var/log/httpd/error_log でした。

[退会済みユーザー]

tailしてみたところ

[Thu Jan 14 12:18:35.358360 2016] [:error] [pid 2559] [client 192.168.248.1:61683] test2

でした。
(画面上にはなにも表示されず。です)

[退会済みユーザー]

この場合は正常ですね。問題ない。

error_log の 第二引数に 3 を指定する場合のみおかしいとことまでは特定できた感じですね。PHP 5.3にバグでもあるのかな…

[退会済みユーザー]

phpinfoで確かめたところ

5.6.13

でした。
バージョンによる影響などあるのでしょうか･･･(?

[退会済みユーザー]

もちろん、バグの修正などでバージョンアップが必要なので、バージョンによって関数の動きが変わることはあります。バグ修正であったり、仕様の変更であったり。

[退会済みユーザー]

はい。なるほどです。

今日はもう限界を突破しているので、、、意識が厳しくなってまして
また改めて問題に取り組みたいと思います。

もしよろしければ、今後ともどうぞよろしくお願いいたします。
ありがとうございました。大変助かりました。

[退会済みユーザー]

お力になれず…おやすみなさい。