PHP

WARNING: Segmentation Faults in these executables

logwatchの出力に以下の記録がありました。
 --------------------- Kernel Begin ------------------------

 WARNING:  Segmentation Faults in these executables
    pgpool :  1 Time(s)

 1 Time(s): Code: 8b 44 24 38 4c 8b 3c 24 8d 50 ff 49 8b 84 24 80 00 00 00 4c 89 ff 48 8d 70 01 e8 5f f6 ff ff 48 89 c7 48 89 04 24 49 8b 47 70 <48> 8b 00 48 85 c0 0f 84 c5 01 00 00 49 8b 57 78 31 f6 ff d0 48 89

 ---------------------- Kernel End -------------------------
そこでmessagesを確認しました。

/var/log/messagesの出力
 # cat messages-20230602 | grep 21:35
Jun  1 21:35:32 sakura kernel: Code: 8b 44 24 38 4c 8b 3c 24 8d 50 ff 49 8b 84 24 80 00 00 00 4c 89 ff 48 8d 70 01 e8 5f f6 ff ff 48 89 c7 48 89 04 24 49 8b 47 70 <48> 8b 00 48 85 c0 0f 84 c5 01 00 00 49 8b 57 78 31 f6 ff d0 48 89
Jun  1 21:35:32 sakura systemd[1]: Started Process Core Dump (PID 3000525/UID 0).
Jun  1 21:35:33 sakura systemd-coredump[3000526]: Resource limits disable core dumping for process 2998804 (pgpool).
Jun  1 21:35:33 sakura systemd-coredump[3000526]: Process 2998804 (pgpool) of user 26 dumped core.
Jun  1 21:35:33 sakura systemd[1]: systemd-coredump@7-3000525-0.service: Succeeded.
コアダンプを確認します。
# coredumpctl info -1
           PID: 2998804 (pgpool)
           UID: 26 (postgres)
           GID: 26 (postgres)
        Signal: 11 (SEGV)
     Timestamp: Thu 2023-06-01 21:35:32 JST (10h ago)
  Command Line: pgpool: ap3 ap2 127.0.0.1(46500) SELECT
    Executable: /usr/bin/pgpool
 Control Group: /system.slice/pgpool.service
          Unit:
         Slice: system.slice
       Boot ID: 271c5cf67c8a43e98f20ff425b76fbb4
    Machine ID: 695a939c5d6449a087f6d36503d37bec
      Hostname: sakura
       Storage: none
       Message: Process 2998804 (pgpool) of user 26 dumped core.
「-1」のオプションは直近のコアダンプを確認するというものです。
マニュアルの記述は以下の通りです。
Show information of a single core dump only, instead of listing all known core dumps.
そういえば最近ちょくちょく同じメッセージがでていたので、すべてのコアダンプを確認します。
# coredumpctl info
           PID: 608872 (pgpool)
           UID: 26 (postgres)
           GID: 26 (postgres)
        Signal: 11 (SEGV)
     Timestamp: Wed 2023-05-24 07:37:23 JST (1 weeks 2 days ago)
  Command Line: pgpool: ap3 ap2 127.0.0.1(59504) SELECT
    Executable: /usr/bin/pgpool
 Control Group: /system.slice/pgpool.service
          Unit:
         Slice: system.slice
       Boot ID: 271c5cf67c8a43e98f20ff425b76fbb4
    Machine ID: 695a939c5d6449a087f6d36503d37bec
      Hostname: sakura
       Storage: none
       Message: Process 608872 (pgpool) of user 26 dumped core.

           PID: 1636000 (pgpool)
           UID: 26 (postgres)
           GID: 26 (postgres)
        Signal: 11 (SEGV)
     Timestamp: Sun 2023-05-28 01:30:35 JST (5 days ago)
  Command Line: pgpool: ap3 ap2 127.0.0.1(37008) SELECT
    Executable: /usr/bin/pgpool
 Control Group: /system.slice/pgpool.service
          Unit:
         Slice: system.slice
       Boot ID: 271c5cf67c8a43e98f20ff425b76fbb4
    Machine ID: 695a939c5d6449a087f6d36503d37bec
      Hostname: sakura
       Storage: none
       Message: Process 1636000 (pgpool) of user 26 dumped core.

           PID: 1827919 (pgpool)
           UID: 26 (postgres)
           GID: 26 (postgres)
        Signal: 11 (SEGV)
     Timestamp: Sun 2023-05-28 18:42:12 JST (4 days ago)
  Command Line: pgpool: ap3 ap2 127.0.0.1(51772) SELECT
    Executable: /usr/bin/pgpool
 Control Group: /system.slice/pgpool.service
          Unit:
         Slice: system.slice
       Boot ID: 271c5cf67c8a43e98f20ff425b76fbb4
    Machine ID: 695a939c5d6449a087f6d36503d37bec
      Hostname: sakura
       Storage: none
       Message: Process 1827919 (pgpool) of user 26 dumped core.

           PID: 1950651 (pgpool)
           UID: 26 (postgres)
           GID: 26 (postgres)
        Signal: 11 (SEGV)
     Timestamp: Mon 2023-05-29 03:30:50 JST (4 days ago)
  Command Line: pgpool: ap3 ap2 127.0.0.1(43044) SELECT
    Executable: /usr/bin/pgpool
 Control Group: /system.slice/pgpool.service
          Unit:
         Slice: system.slice
       Boot ID: 271c5cf67c8a43e98f20ff425b76fbb4
    Machine ID: 695a939c5d6449a087f6d36503d37bec
      Hostname: sakura
       Storage: none
       Message: Process 1950651 (pgpool) of user 26 dumped core.

           PID: 2998804 (pgpool)
           UID: 26 (postgres)
           GID: 26 (postgres)
        Signal: 11 (SEGV)
     Timestamp: Thu 2023-06-01 21:35:32 JST (10h ago)
  Command Line: pgpool: ap3 ap2 127.0.0.1(46500) SELECT
    Executable: /usr/bin/pgpool
 Control Group: /system.slice/pgpool.service
          Unit:
         Slice: system.slice
       Boot ID: 271c5cf67c8a43e98f20ff425b76fbb4
    Machine ID: 695a939c5d6449a087f6d36503d37bec
      Hostname: sakura
       Storage: none
       Message: Process 2998804 (pgpool) of user 26 dumped core.

前に同じ事象が発生したときは、php-fpmのrestartで回復したので、とりあえずphp-fpmをrestartしました。
# systemctl restart php-fpm.service
コアダンプはgdbで見られるそうなので、見ようとしたところコアダンプがありませんでした…

# coredumpctl gdb -1
           PID: 2998804 (pgpool)
           UID: 26 (postgres)
           GID: 26 (postgres)
        Signal: 11 (SEGV)
     Timestamp: Thu 2023-06-01 21:35:32 JST (10h ago)
  Command Line: pgpool: ap3 ap2 127.0.0.1(46500) SELECT
    Executable: /usr/bin/pgpool
 Control Group: /system.slice/pgpool.service
          Unit:
         Slice: system.slice
       Boot ID: 271c5cf67c8a43e98f20ff425b76fbb4
    Machine ID: 695a939c5d6449a087f6d36503d37bec
      Hostname: sakura
       Storage: none
       Message: Process 2998804 (pgpool) of user 26 dumped core.

Coredump entry has no core attached (neither internally in the journal nor externally on disk).
ulimitコマンドで確認すると、core file sizeが0でしたので…、unlimitedに変更しました。
# ulimit -a
core file size          (blocks, -c) 0
# ulimit -c unlimited
# ulimit -a
core file size          (blocks, -c) unlimited
また再起動後も設定を有効にするため、以下のように設定しました。
# emacs /etc/security/limits.d/90-core.conf
90-core.confに以下の内容を追加
* soft core unlimited
* hard core unlimited
すべてのユーザー(*)に対してソフトおよびハードの core file size を無制限に設定します。
特定のユーザーだけに適用したい場合、* の代わりにユーザー名を使用します。

次にコアダンプをグローバルに有効にします。
# emacs /etc/sysctl.conf
/etc/sysctl.confに以下の内容を追加
kernel.core_pattern = /coredumpsへのパス/core.%e.%p
fs.suid_dumpable = 2
この設定は、コアダンプファイルのファイル名を設定し、SUIDプログラムでもコアダンプが生成されるようにしています。
設定を反映します。
# sudo sysctl -p
コアダンプを保存するディレクトリが、すべてのユーザーに対して書き込み可能にします。
sudo mkdir -p /coredumpsへのパス
sudo chmod 1777 /coredumpsへのパス
コアダンプが生成されているかどうかをテストするために、クラッシュする簡単なプログラムを作成して実行します。
crash.c
#include <stdlib.h>

int main() {
    abort();
}
コンパイルして実行し、指定したディレクトリにコアダンプファイルが生成されることを確認します。
$ gcc -o crash crash.c
$ ./crash
$ ls -l /var/tmp/core/
total 160
-rw------- 1 ap2 ap2 253952 Jun 15 08:09 core.crash.2340294
2023/06/19 追記
まだコアダンプが生成されませんでした。
#  coredumpctl gdb -1
           PID: 1964404 (pgpool)
           UID: 26 (postgres)
           GID: 26 (postgres)
        Signal: 11 (SEGV)
     Timestamp: Wed 2023-06-14 00:43:50 JST (5 days ago)
  Command Line: pgpool: ap3 ap2 127.0.0.1(36308) SELECT
    Executable: /usr/bin/pgpool
 Control Group: /system.slice/pgpool.service
          Unit:
         Slice: system.slice
       Boot ID: 35ca3e38a1bd486194253de42de9c7c7
    Machine ID: 695a939c5d6449a087f6d36503d37bec
      Hostname: sakura
       Storage: none
       Message: Process 1964404 (pgpool) of user 26 dumped core.

Coredump entry has no core attached (neither internally in the journal nor externally on disk).
pgpoolのプロセスのmax core file sizeを確認したところ、SOFTが0になっていました。
# ps ax | grep pgpool | more
3257315 ?        Ss     0:17 /usr/bin/pgpool -f /etc/pgpool-II/pgpool.conf -n
(以下略)

# prlimit 3257315
RESOURCE   DESCRIPTION                             SOFT      HARD UNITS
AS         address space limit                unlimited unlimited bytes
CORE       max core file size                 unlimited unlimited bytes
(以下略)
pgpoolのソフトリミットをunlimitedに変更します。
# prlimit --pid 3257315 --core=unlimited:unlimited
また、pgpoolのサービスユニットファイルを変更して、LimitCOREをinfinityにしておきます。
まずサービスユニットファイルの場所を確認します。
# systemctl status pgpool.service
● pgpool.service - Pgpool-II
   Loaded: loaded (/usr/lib/systemd/system/pgpool.service; enabled; vendor preset: disabled)
以下の通り設定を追加します。
[Unit]
Description=Pgpool-II
After=syslog.target network.target

[Service]

User=postgres
Group=postgres

EnvironmentFile=-/etc/sysconfig/pgpool

LimitCORE=infinity
ExecStart=/usr/bin/pgpool -f /etc/pgpool-II/pgpool.conf $OPTS
ExecStop=/usr/bin/pgpool -f /etc/pgpool-II/pgpool.conf $STOP_OPTS stop
ExecReload=/usr/bin/pgpool -f /etc/pgpool-II/pgpool.conf reload

[Install]
WantedBy=multi-user.target

2023/07/01追記
事象が再現しましたので、コアダンプを確認しようとしたところ、以下のように出力されました。
# coredumpctl info -1
No match found.
なにか設定にしくじっていると思います…
coredumpctlはsystemdで動く…という表現でいいのかな…のですが、先日の設定のどこかでsystemdと競合する何かを設定してしまっている気がします。
コアダンプファイルを出力するように設定した/var/tmp/core/ディレクトリに、コアダンプファイルが生成されていましたので、とりあえず解析をすることにしました。
# ls -l /var/tmp/core/
-rw------- 1 postgres postgres 154488832 Jun 30 16:59 core.pgpool.3071815
解析方法は初心者のためのコアファイルの解析方法についてを読んで実施しました。
# gdb /usr/bin/pgpool /var/tmp/core/core.pgpool.3071815
GNU gdb (GDB) Red Hat Enterprise Linux 8.2-19.el8
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later 
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
.
Find the GDB manual and other documentation resources online at:
    .

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/bin/pgpool...Reading symbols from /usr/lib/debug/usr/bin/pgpool-4.1.16-1pgdg.rhel8.x86_64.debug...done.
done.

warning: Can't open file (null) during file-backed mapping note processing

warning: Can't open file (null) during file-backed mapping note processing

warning: Can't open file (null) during file-backed mapping note processing

warning: Can't open file (null) during file-backed mapping note processing

warning: Can't open file (null) during file-backed mapping note processing

warning: Can't open file (null) during file-backed mapping note processing

warning: Can't open file (null) during file-backed mapping note processing

warning: Can't open file (null) during file-backed mapping note processing

warning: Can't open file (null) during file-backed mapping note processing

warning: Can't open file (null) during file-backed mapping note processing

warning: Can't open file (null) during file-backed mapping note processing

warning: Can't open file (null) during file-backed mapping note processing

warning: Can't open file (null) during file-backed mapping note processing
[New LWP 3071815]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `pgpool: ap3 ap2 127.0.0.1(34752) SELECT         '.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00005589153a0ffc in psql_yylex (yylval_param=yylval_param@entry=0x0, yyscanner=<optimized out>)
    at utils/psqlscan.l:712
712                                                     value = cur_state->callbacks->get_variable(varname,
(gdb) backtrace
#0  0x00005589153a0ffc in psql_yylex (yylval_param=yylval_param@entry=0x0, yyscanner=<optimized out>)
    at utils/psqlscan.l:712
#1  0x00005589153a1a67 in psql_scan (state=state@entry=0x5589164a15d8, query_buf=query_buf@entry=0x7ffd2f6f0250,
    prompt=prompt@entry=0x7ffd2f6f024c) at utils/psqlscan.l:1149
#2  0x0000558915368f0e in multi_statement_query (
    queries=0x558916486de8 "SELECT \r\n\t'\r\n<!-- jQuery library  -->\r\n<script type=\"text/javascript\" src=\"https://code.jquery.com/jquery-1.11.1.min.js\"></script>\r\n<!-- WEB Fonts  -->\r\n<link href=\\'http://fonts.googleapis.com/css?fa"...) at protocol/pool_proto_modules.c:4131
#3  SimpleQuery (frontend=frontend@entry=0x5589164474f8, backend=backend@entry=0x7fb6f19bb9d0, len=107421,
    contents=contents@entry=0x558916486de8 "SELECT \r\n\t'\r\n<!-- jQuery library  -->\r\n<script type=\"text/javascript\" src=\"https://code.jquery.com/jquery-1.11.1.min.js\"></script>\r\n<!-- WEB Fonts  -->\r\n<link href=\\'http://fonts.googleapis.com/css?fa"...) at protocol/pool_proto_modules.c:266
#4  0x000055891536ef30 in ProcessFrontendResponse (frontend=frontend@entry=0x5589164474f8,
    backend=backend@entry=0x7fb6f19bb9d0) at protocol/pool_proto_modules.c:2597
#5  0x0000558915360d6e in read_packets_and_process (frontend=<optimized out>, backend=<optimized out>,
    reset_request=<optimized out>, state=<optimized out>, num_fields=<optimized out>, cont=<optimized out>)
    at protocol/pool_process_query.c:4986
#6  0x00005589153615e3 in pool_process_query (frontend=<optimized out>, backend=<optimized out>,
    reset_request=<optimized out>) at protocol/pool_process_query.c:291
#7  0x000055891535b0f8 in do_child (fds=fds@entry=0x558916445de0) at protocol/child.c:431
#8  0x0000558915332467 in fork_a_child (fds=0x558916445de0, id=57) at main/pgpool_main.c:703
#9  0x0000558915332cd9 in reaper () at main/pgpool_main.c:2855
#10 0x000055891533aa64 in PgpoolMain (discard_status=<optimized out>, clear_memcache_oidmaps=<optimized out>)
    at main/pgpool_main.c:491
#11 0x0000558915330715 in main (argc=<optimized out>, argv=0x7ffd2f700318) at main/main.c:356
(gdb) list
707
708                                             varname = psqlscan_extract_substring(cur_state,
709                                                                                                                      yytext + 1,
710                                                                                                                      yyleng - 1);
711                                             if (cur_state->callbacks->get_variable)
712                                                     value = cur_state->callbacks->get_variable(varname,
713                                                                                                                           PQUOTE_PLAIN,
714                                                                                                                           cur_state->cb_passthrough);
715                                             else
716                                                     value = NULL;
(gdb) info locals
varname = 0x5589164a1668 "first"
value = 
cur_state = 
output_buf = 
yyless_macro_arg = 
yyless_macro_arg = 
yyless_macro_arg = 
yyless_macro_arg = 
yyless_macro_arg = 
yyless_macro_arg = 
yy_current_state = 
yy_cp = 
yy_bp = 0x5589164a7780 ":first"
yy_act = 
yyg = 
backtraceで表示されているSQLを検索して実行したところ、Segmentation faultしました。 このSQLはユーザーさんが作成されたもので、現在のPostgreSQLではそもそも動かないSQLであることを確認したので無効化しました。 なぜSegmentation faultするかの原因を探りたかったのですが、元のSQLが複雑すぎることと、現在のシングルクォーテーションのエスケープ方法ではないエスケープ方法を使っていたので諦めました。

Cookieをセットしてfile()でWebページを取得する

ErogameScapeのキャンペーン情報は、FANZAやDLsiteのキャンペーンの情報の画面のHTMLを取得し、ErogameScapeで持っている情報と突き合わせて、生成しています。
HTMLの取得は
$data = file("https://dlsoft.dmm.co.jp/list/article=keyword/id=300080/sort=ranking/");
のようにしていました。
しかし、2021/12/01時点で、この方法で取得しようとすると、「あなたは18歳以上ですか?」の画面に飛ばされるようになりました。

「あなたは18歳以上ですか?」で「はい」を選択すると、レスポンスヘッダーに
set-cookie: age_check_done=1; expires=Fri, 31-Dec-2021 06:48:55 GMT; path=/; domain=dmm.co.jp; httponly
が含まれるレスポンスがかえってきて、再度、https://dlsoft.dmm.co.jp/list/article=keyword/id=300080/sort=ranking/にアクセスする、という流れになります。

以上から、file()を呼ぶときに、「Cookie: age_check_done=1」を追加する必要がでてきました。
$options =array(
    'http' =>array(
    'method' => "GET",
    'header' => "Cookie: age_check_done=1\r\n",
    )
);
$data = file("https://dlsoft.dmm.co.jp/list/article=keyword/id=300080/sort=ranking/", 0, $options);
とすることで、https://dlsoft.dmm.co.jp/list/article=keyword/id=300080/sort=ranking/の内容を取得することができました。

[参考]



Cannot change a fulfilled promise to rejected

phpを7.3からphp8.0にあげるためのスクリプト確認中に以下の事象が発生しました。

[事象]
paapi5-php-sdkを使ったスクリプトでAmazonのProduct Advertising APIから情報を取得しようとすると以下のエラーメッセージを出力してスクリプトが停止する。
Cannot change a fulfilled promise to rejected
[詳細]
paapi5-php-sdkのGetItems.phpのfunction getItemsAsync()において、$exceptionの詳細を確認するため以下のようにスクリプトを変更しました。
    try {
        $promise = $apiInstance->getItemsAsync($getItemsRequest);
        $response = $promise->wait();
        $promise->then(
            function ($response) {
                return $response;
            },
            function (\Exception $exception) {
                return FALSE;
            }
        );

        echo $response, PHP_EOL;
    } catch (ApiException $exception) {
      return FALSE;
    } catch (Exception $exception) {
      var_dump($exception); → 追加
      return FALSE;
    }
$exceptionの内容は以下のとおりでした。
object(LogicException)#20 (7) {
  ["message":protected]=>
  string(45) "Cannot change a fulfilled promise to rejected"
  ["string":"Exception":private]=>
  string(0) ""
  ["code":protected]=>
  int(0)
  ["file":protected]=>
  string(72) "/paapi5-php-sdk/vendor/guzzlehttp/promises/src/Promise.php"
  ["line":protected]=>
  int(130)
  ["trace":"Exception":private]=>
  array(13) {
    [0]=>
    array(6) {
      ["file"]=>
      string(72) "/paapi5-php-sdk/vendor/guzzlehttp/promises/src/Promise.php"
      ["line"]=>
      int(118)
      ["function"]=>
      string(6) "settle"
      ["class"]=>
      string(26) "GuzzleHttp\Promise\Promise"
      ["type"]=>
      string(2) "->"
      ["args"]=>
      array(2) {
        [0]=>
        string(8) "rejected"
        [1]=>
        object(TypeError)#98 (7) {
          ["message":protected]=>
          string(90) "method_exists(): Argument #1 ($object_or_class) must be of type object|string, array given"
          ["string":"Error":private]=>
          string(0) ""
          ["code":protected]=>
          int(0)
          ["file":protected]=>
          string(72) "/paapi5-php-sdk/vendor/guzzlehttp/promises/src/Promise.php"
          ["line":protected]=>
          int(151)
Promise.phpの151行目は以下のとおりでした。
if (!method_exists($value, 'then')) {
PHP8かPHP7.4で、method_existsの第一引数にobject/string以外の型を渡すとerrorになるように変更されたのかな…
if (!method_exists((object)$value, 'then')) {
と書くと動くことを確認しました。
おそらく最新のguzzlehttpなら動くと思い、guzzlehttpを最新のリビジョン(6.5.5)にあげたところ動作しました。
該当部分は
if (!is_object($value) || !method_exists($value, 'then')) {
と修正されていました。
自分がpaapi5-php-sdkを使い始めたのはProduct Advertising API 5の導入時期でした。
今のpaapi5-php-sdkを確認したところ、同梱されているguzzlehttpは6.5.3でしたので問題ないです。
自分と同じようにpaapi5-php-sdkを初期に導入して何もしていない…場合は、PHPを7.3から8.0にあげると同じエラーがでるかなと思います。





muninがPostgreSQLから情報をとれなくなるほど負荷があがる

ここ1ヶ月ほどmuninがPostgreSQLから情報をとれなくなるほど負荷があがることが1日に1,2回程度発生していました。
以下の赤い四角で囲った部分です。
グラフがぽっかり抜けています。
001
スロークエリがあると想定してログを取得するも、問題となるようなクエリはありませんでした。
実行に時間がかかっているクエリはたくさんあったのですが、いずれのクエリも平常時はms単位で応答を返すものでした。
が、この事象が発生するときは、応答に5秒かかる…というような状態でした。
sarを実行すると以下のような出力が得られました。

06時40分01秒     CPU     %user     %nice   %system   %iowait    %steal     %idle
06時41分01秒     all      7.36      2.01      3.00      0.58      0.00     87.05
06時42分01秒     all      4.46      0.00      1.79      0.32      0.00     93.43
06時43分01秒     all      4.87      0.00      1.55      0.43      0.00     93.15
06時44分01秒     all      6.98      0.00      2.56      0.26      0.00     90.19
06時45分01秒     all     13.59      0.00      5.06      0.24      0.00     81.11
06時46分01秒     all     45.36      1.99     17.29      0.30      0.00     35.06
06時47分01秒     all     74.13      0.00     25.38      0.00      0.00      0.49
06時48分01秒     all     74.97      0.00     24.87      0.00      0.00      0.16
06時49分02秒     all     76.15      0.00     23.46      0.00      0.00      0.39
06時50分01秒     all     44.06      0.00     14.09      0.08      0.00     41.77
06時51分01秒     all     14.55      1.98      5.38      0.90      0.00     77.19
06時52分01秒     all      9.73      0.00      2.82      0.31      0.00     87.14
※sarはCentOSの場合、デフォルトでは10分に1回記録するようになっていますが、10分だと問題が発生したときにログを見るのがつらいので1分に変更すべきだと思います。ちなみに、この問題が発生したとき、DBサーバーは10分間隔だったで…1分に変更しました。

userとsystemでCPU時間を100%使いつくしている状態です。
負荷が高いのはPostgreSQLを動かしているサーバーで、Apacheを動かしているサーバーの負荷は問題ありませんでした。
以上から、PostgreSQLでなにか起こっているに違いないと思って、いろいろ切り分けたのですが、PostgreSQLのログを見ても何もわかりませんでした。

何か多くのアクセスがきているのが原因かもしれないと思い、Apacheのログを見たのですが、何かが起こっている06時46分と何も起こってない時間のアクセス数はあまりかわらず、多くのアクセスがきているわけではなさそうでした。

アクセス数はかわらないのですが、どこからアクセスがきているのか?を集計したところ、bingbotが多くをしめていました。
bingbotにしぼって06時45分のログを見たのが以下です。
207.46.13.34	[30/Apr/2020:06:45:27+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=6151 HTTP/1.1	200	49991
40.77.167.157	[30/Apr/2020:06:45:30+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=19208 HTTP/1.1	200	51751
40.77.167.157	[30/Apr/2020:06:45:22+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=2830 HTTP/1.1	200	50266
207.46.13.34	[30/Apr/2020:06:45:22+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=9955 HTTP/1.1	200	51289
40.77.167.157	[30/Apr/2020:06:45:24+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=2041 HTTP/1.1	200	50478
40.77.167.186	[30/Apr/2020:06:45:39+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=21480 HTTP/1.1	504	247
40.77.167.186	[30/Apr/2020:06:45:39+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=20671 HTTP/1.1	504	247
40.77.167.186	[30/Apr/2020:06:45:39+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=20632 HTTP/1.1	504	247
207.46.13.34	[30/Apr/2020:06:45:43+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=16545 HTTP/1.1	504	247
soukan.phpにそこそこな頻度でアクセスした結果、504を返しています。
soukan.phpはあるゲームに似た評価をされているゲームを表示するスクリプトです。
このスクリプトは作りが悪くて…SQLを1万回程度実行するスクリプトです。
SQL自体は0.006秒程度で応答を返すのですが、それを1万回実行するので…応答がかえるまでに60秒程度かかります。
実行に60秒程度かかるスクリプトをだいたい5秒おきに実行されてしまったので負荷が高くなったようでした。

自分は、DBのネックで負荷があがる場合は、iowaitが高くなると思い込んでいたのですが、1つのスクリプトで応答時間は短いけどSQLを大量に発行して処理が追いつかなくなる場合は、userやsystemが高くなる…ということを知りました。

本格対処はsoukan.phpを書き換えることなのですが、暫定対処として、bingbotをブロックすることにしました。

phpだけ404の場合に自分で設定した404用のページが表示されず「File not found. 」とだけ表示される

Apache + php-fpmの環境の話題です。

ErogameScapeではファイルが存在しないURLが指定された場合、ルートディレクトリのindex.phpを表示するように設定しています。
ErrorDocument 404 /~ap2/index.php
PHPをApacheのモジュールとして動かしていた場合には問題が発生していなかったのですが、PHPをCGIとして動作させた場合に以下の問題が発生しました。

phpだけ404の場合に自分で設定した404用のページが表示されず「File not found. 」とだけ表示される。

https://erogamescape.dyndns.org/~ap2/ero/toukei_kaiseki/a
とすると(aは存在しないです)、自分が設定した404用のページが表示されるのに
https://erogamescape.dyndns.org/~ap2/ero/toukei_kaiseki/a.php
とすると(a.phpも存在しないです)、「File not found. 」とだけ表示されてます。
404
php-fpmを動かすのに、ErogameScapeではunixドメインソケット経由で動かしているので設定ファイルに以下の記述をしています。
<FilesMatch \.php$>
    SetHandler proxy:fcgi://php-fpm
</FilesMatch>
apacheが受けた要求をphp-fpmに渡して、php-fpmが処理した結果をapacheが受けて、apacheがクライアントに返却します。
a.phpの要求を受けたapacheはphp-fpmに渡して、php-fpmはa.phpがないので、「File not found. 」をapacheに返し、apacheはそれを見たそのままクライアントに返却するので、自分が設定した404用のページが表示されません。

php-fpmが返してきた「File not found. 」(404)をapacheが上書きする設定が以下のディレクティブです。

設定ファイルに以下の記述すると自分が設定した404用のページを表示してくれます。
ProxyErrorOverride on
※php-fpmがどうやって「File not found. 」という文字列を返しているのかは分かりませんでした…返す文字列を設定しているっぽいファイルは見つけられなかったのでソースに埋め込まれているのでしょうか…



php-pearのインストールにはepelを有効にする必要がある

この文書は2018/11/23時点の情報です。
php-pearをインストールしようとしたら、php-composer(fedora/autoloader)が必要でした。

[root@localhost localuser]# yum install php-pear
Loaded plugins: fastestmirror, langpacks, priorities
Loading mirror speeds from cached hostfile
 * base: ftp.iij.ad.jp
 * extras: ftp.iij.ad.jp
 * remi-php71: repo1.sea.innoscale.net
 * remi-safe: repo1.sea.innoscale.net
 * updates: ftp.iij.ad.jp
Resolving Dependencies
--> Running transaction check
---> Package php-pear.noarch 1:1.10.6-1.el7.remi will be installed
--> Processing Dependency: php-composer(fedora/autoloader) for package: 1:php-pear-1.10.6-1.el7.remi.noarch
--> Finished Dependency Resolution
Error: Package: 1:php-pear-1.10.6-1.el7.remi.noarch (remi-php71)
           Requires: php-composer(fedora/autoloader)
 You could try using --skip-broken to work around the problem

php-composer(fedora/autoloader)はepelにあるので、まずepelが使えるようにします。
epelのリポジトリを追加するためのrpmを持ってきます。
[root@localhost localuser]# wget https://dl.fedoraproject.org/pub/epel/7/x86_64/Packages/e/epel-release-7-11.noarch.rpm
--2018-11-18 12:28:04--  https://dl.fedoraproject.org/pub/epel/7/x86_64/Packages/e/epel-release-7-11.noarch.rpm
Resolving dl.fedoraproject.org (dl.fedoraproject.org)... 209.132.181.24, 209.132.181.23, 209.132.181.25
Connecting to dl.fedoraproject.org (dl.fedoraproject.org)|209.132.181.24|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 15080 (15K) [application/x-rpm]
Saving to: ‘epel-release-7-11.noarch.rpm’

100%[==================================================================================>] 15,080      --.-K/s   in 0.1s

2018-11-18 12:28:04 (109 KB/s) - ‘epel-release-7-11.noarch.rpm’ saved [15080/15080]

epelのリポジトリを追加するためのrpmをインストールします。
[root@localhost localuser]# rpm -Uvh epel-release-7-11.noarch.rpm
Preparing...                          ################################# [100%]
        package epel-release-7-11.noarch is already installed
[root@localhost localuser]# yum install php-fedora-autoloader
Loaded plugins: fastestmirror, langpacks, priorities
Loading mirror speeds from cached hostfile
 * base: ftp.iij.ad.jp
 * extras: ftp.iij.ad.jp
 * remi-php71: repo1.sea.innoscale.net
 * remi-safe: repo1.sea.innoscale.net
 * updates: ftp.iij.ad.jp
No package php-fedora-autoloader available.
Error: Nothing to do

epelのリポジトリを有効にするため、epel.repoのenabledを1にします。
[root@localhost localuser]# emacs /etc/yum.repos.d/epel.repo

[epel]
name=Extra Packages for Enterprise Linux 7 - $basearch
#baseurl=http://download.fedoraproject.org/pub/epel/7/$basearch
mirrorlist=https://mirrors.fedoraproject.org/metalink?repo=epel-7&arch=$basearch
failovermethod=priority
enabled=1
gpgcheck=1
gpgkey=file:///etc/pki/rpm-gpg/RPM-GPG-KEY-EPEL-7

php-fedora-autoloaderをインストールします。
[root@localhost localuser]# yum install php-fedora-autoloader
Loaded plugins: fastestmirror, langpacks, priorities
Loading mirror speeds from cached hostfile
epel/x86_64/metalink                                                                                 | 9.5 kB  00:00:00
 * base: ftp.iij.ad.jp
 * epel: www.ftp.ne.jp
 * extras: ftp.iij.ad.jp
 * remi-php71: repo1.sea.innoscale.net
 * remi-safe: repo1.sea.innoscale.net
 * updates: ftp.iij.ad.jp
epel                                                                                                 | 3.2 kB  00:00:00
(1/3): epel/x86_64/group_gz                                                                          |  88 kB  00:00:00
epel/x86_64/updateinfo         FAILED                                                     ]  0.0 B/s |  88 kB  --:--:-- ETA
http://mirror2.totbb.net/epel/7/x86_64/repodata/4965e91e8ce6cc40f06cbce2777f2ef21bf69cae86e12e9c8d0b8c3375a4fcbc-updateinfo.xml.bz2: [Errno 14] HTTP Error 404 - Not Found
Trying other mirror.
To address this issue please refer to the below wiki article

https://wiki.centos.org/yum-errors

If above article doesn't help to resolve this issue please use https://bugs.centos.org/.

(2/3): epel/x86_64/updateinfo                                                                        | 932 kB  00:00:00
(3/3): epel/x86_64/primary                                                                           | 3.6 MB  00:00:02
epel                                                                                                            12707/12707
Resolving Dependencies
--> Running transaction check
---> Package php-fedora-autoloader.noarch 0:1.0.0-1.el7 will be installed
--> Finished Dependency Resolution

Dependencies Resolved

============================================================================================================================
 Package                                Arch                    Version                         Repository             Size
============================================================================================================================
Installing:
 php-fedora-autoloader                  noarch                  1.0.0-1.el7                     epel                  9.6 k

Transaction Summary
============================================================================================================================
Install  1 Package

Total download size: 9.6 k
Installed size: 15 k
Is this ok [y/d/N]: y
Downloading packages:
php-fedora-autoloader-1.0.0-1.el7.noarch.rpm                                                         | 9.6 kB  00:00:00
Running transaction check
Running transaction test
Transaction test succeeded
Running transaction
  Installing : php-fedora-autoloader-1.0.0-1.el7.noarch                                                                 1/1
  Verifying  : php-fedora-autoloader-1.0.0-1.el7.noarch                                                                 1/1

Installed:
  php-fedora-autoloader.noarch 0:1.0.0-1.el7

Complete!

php-pearをインストールします。
[root@localhost localuser]# yum install php-pear
Loaded plugins: fastestmirror, langpacks, priorities
Loading mirror speeds from cached hostfile
 * base: ftp.iij.ad.jp
 * epel: www.ftp.ne.jp
 * extras: ftp.iij.ad.jp
 * remi-php71: repo1.sea.innoscale.net
 * remi-safe: repo1.sea.innoscale.net
 * updates: ftp.iij.ad.jp
Resolving Dependencies
--> Running transaction check
---> Package php-pear.noarch 1:1.10.6-1.el7.remi will be installed
--> Finished Dependency Resolution

Dependencies Resolved

============================================================================================================================
 Package                   Arch                    Version                                Repository                   Size
============================================================================================================================
Installing:
 php-pear                  noarch                  1:1.10.6-1.el7.remi                    remi-php71                  357 k

Transaction Summary
============================================================================================================================
Install  1 Package

Total download size: 357 k
Installed size: 2.1 M
Is this ok [y/d/N]: y
Downloading packages:
php-pear-1.10.6-1.el7.remi.noarch.rpm                                                                | 357 kB  00:00:01
Running transaction check
Running transaction test
Transaction test succeeded
Running transaction
  Installing : 1:php-pear-1.10.6-1.el7.remi.noarch                                                                      1/1
  Verifying  : 1:php-pear-1.10.6-1.el7.remi.noarch                                                                      1/1

Installed:
  php-pear.noarch 1:1.10.6-1.el7.remi

Complete!

php7.1で複数のRedisサーバーをsession.save_handlerに設定しても冗長構成にはならない

原因は分からないのですが、待機系サーバーのmemcashedの動作がおかしい気がする…ので、session.save_handlerとして使っているmemcashedの別の候補として、PHP7.1において、session.save_handlerとして、Redisを使用したいと思いました。

session.save_pathには複数のRedisサーバーを設定すれば、Redisサーバーが1つ落ちてもサービスを継続できるかな…と思いましたが出来ませんでした。

環境は以下の通りです。
  • CentOS6および7
  • PHP 7.1.0
  • Redis server version 2.4.10
  • phpredis 3.1.1RC2
RedisをSession handlerとして使うには以下の設定が必要です。

/etc/php.iniに以下を記述
session.save_handler = redis
session.save_path = "tcp://localhost:6379"
extension=redis.so

さて、PhpRedisにREADMEによるとsession.save_pathには複数のサーバーを指定できるようになっています。
https://github.com/phpredis/phpredis/blob/develop/README.markdown#user-content-php-session-handler

そこで以下のように記述すれば1つサーバーが落ちてもサービスを継続できると思いました。
session.save_path = "tcp://localhost:6379, tcp://192.168.0.14:6379"

localhostと192.168.0.14にRedisで起動 → 192.168.0.14にセッションの情報が記録されることを確認
localhostのみRedisを起動 → NG、以下のエラーメッセージが出る

Warning: session_start(): connect() failed: Connection refused
Warning: session_start(): Failed to read session data: redis (path: tcp://localhost:6379, tcp://192.168.0.14:6379)

ちなみにsession.save_path = "tcp://localhost:6379"と書くと、localhostにセッションの情報が記録されるのでlocalhostの設定は問題ありません。

振り分けロジックは分からないのですが、逆のケースもNGです。

localhostと192.168.0.14にRedisで起動 → localhostにセッションの情報が記録されることを確認
192.168.0.14のみRedisを起動 → NG


memcashedとmemcasheの場合、session.save_pathに複数のサーバーを記述すれば、すべてのサーバーに同じ情報を書き込むため、サーバーが1台落ちても問題ないのですが、PhpRedisの場合はsession.save_pathに複数サーバーを書くと負荷分散するだけで、サーバーが落ちた場合の対処は別に仕組みを整えないといけないです。
具体的にどうするかというと以下のドキュメントにいろいろな構成が書いてあります。
http://tech.gmo-media.jp/post/48748908427/introduce-redis-sentinel

お手軽に冗長構成をとれたらいいなあ…と思っていたのですが、どの構成もそこそこ手間がかかって、ここまでして冗長構成を取る必要も無いかなあ…と思ったのでRedisは導入を見送ろうと思いました。

php7とphp5のlist関数の挙動の違いについて

ErogameScapeでは以下のようにPostgrelSQLのdate型の列から取り出した日付を年月日に分解するスクリプトがあります。
$ php -r 'list($year,$month,$day) = sscanf("2016-02-23","%d-%d-%d"); var_dump($year);'
Command line code:1:
int(2016)
上記をタイポして以下のように記述しているところがありました。
list($year,$month,$year) = sscanf("2016-02-23","%d-%d-%d");
PHP5までは問題なく…動いていました。
$ php -r 'list($year,$month,$year) = sscanf("2016-02-23","%d-%d-%d"); var_dump($year);'
Command line code:1:
int(2016)
しかし、PHP7で挙動がかわって以下のように日付が抽出されるようになりました。
$ php -r 'list($year,$month,$year) = sscanf("2016-02-23","%d-%d-%d"); var_dump($year);'
Command line code:1:
int(23)
タイポを直して解決しました。

PHP5.6にあげたらpear Net_SMTPからメールが送れない

PHPを5.6にあげたら
port 587番
auth true
の設定でpear Net_SMTPからメールが送れていませんでした。
結論から書くと、Net_SMTPを最新のVer(2015/12/21時点で1.7.1)にあげたら送れるようになりました。
※ちなみに当時使用していたNet_SMTPのVerは1.6.0でした…
$ pear list
Installed packages, channel pear.php.net:
=========================================
中略
Net_SMTP         1.6.0      stable

#pear install -a Net_SMTP

$ pear list
Installed packages, channel pear.php.net:
=========================================
中略
Net_SMTP         1.7.1      stable

pear Net_SMTPからメールが送れなくなる | 東京ネット工務店に「最新版では直っているかも知れません。」と書いてありますが、おそらく直っています。
おそらくと書いたのは、何が良くなかったのかを把握していないから…です。

以下、pearのMail.phpのdebugをtrueにしたときのメッセージです。
Net_SMTPが1.6.0のときは以下のようなメッセージでした。
DEBUG: Recv: 220 ***.***.***.*** ESMTP Sendmail 8.14.5/8.14.5; Mon, 21 Dec 2015 10:38:50 +0900 (JST)
DEBUG: Send: EHLO localhost

DEBUG: Recv: 250-***.***.***.*** Hello ***.***.***.*** [***.***.***.***], pleased to meet you
DEBUG: Recv: 250-ENHANCEDSTATUSCODES
DEBUG: Recv: 250-PIPELINING
DEBUG: Recv: 250-8BITMIME
DEBUG: Recv: 250-SIZE 209715200
DEBUG: Recv: 250-DSN
DEBUG: Recv: 250-AUTH CRAM-MD5 DIGEST-MD5 LOGIN PLAIN
DEBUG: Recv: 250-STARTTLS
DEBUG: Recv: 250-DELIVERBY
DEBUG: Recv: 250 HELP
DEBUG: Send: STARTTLS

DEBUG: Recv: 220 2.0.0 Ready to start TLS
DEBUG: Send: RSET
なぜかRSETを返します。
Net_SMTPを1.7.1にあげた際のメッセージは以下のとおりです。
DEBUG: Recv: 220 ***.***.***.*** ESMTP Sendmail 8.14.5/8.14.5; Mon, 21 Dec 2015 11:28:38 +0900 (JST)
DEBUG: Send: EHLO localhost

DEBUG: Recv: 250-***.***.***.*** Hello ***.***.***.*** [***.***.***.***], pleased to meet you
DEBUG: Recv: 250-ENHANCEDSTATUSCODES
DEBUG: Recv: 250-PIPELINING
DEBUG: Recv: 250-8BITMIME
DEBUG: Recv: 250-SIZE 209715200
DEBUG: Recv: 250-DSN
DEBUG: Recv: 250-AUTH CRAM-MD5 DIGEST-MD5 LOGIN PLAIN
DEBUG: Recv: 250-STARTTLS
DEBUG: Recv: 250-DELIVERBY
DEBUG: Recv: 250 HELP
DEBUG: Send: STARTTLS

DEBUG: Recv: 220 2.0.0 Ready to start TLS
DEBUG: Send: EHLO localhost

DEBUG: Recv: 250-***.***.***.*** Hello ***.***.***.*** [***.***.***.***], pleased to meet you
DEBUG: Recv: 250-ENHANCEDSTATUSCODES
DEBUG: Recv: 250-PIPELINING
DEBUG: Recv: 250-8BITMIME
DEBUG: Recv: 250-SIZE 209715200
DEBUG: Recv: 250-DSN
DEBUG: Recv: 250-AUTH CRAM-MD5 DIGEST-MD5 LOGIN PLAIN
DEBUG: Recv: 250-DELIVERBY
DEBUG: Recv: 250 HELP
DEBUG: Send: AUTH DIGEST-MD5

DEBUG: Recv: 334 ****************************
DEBUG: Send: ********************************

DEBUG: Recv: 334 ****************************
DEBUG: Send:

DEBUG: Recv: 235 2.0.0 OK Authenticated
DEBUG: Send: MAIL FROM:<***.***.***.***>

DEBUG: Recv: 250 2.1.0 <***.***.***.***>... Sender ok
DEBUG: Send: RCPT TO:<***.***.***.***>

DEBUG: Recv: 250 2.1.5 <***.***.***.***>... Recipient ok
DEBUG: Send: DATA

DEBUG: Recv: 354 Enter mail, end with "." on a line by itself
DEBUG: Send: From: erogamescape@ap2.sakura.ne.jp
to: erscape@apost.plala.or.jp
Subject: =?ISO-2022-JP?*****************************

+`*?>+`*
+`*?>+`* ← 暗号化されたメッセージ
+`*?>+`*
DEBUG: Send:
.

DEBUG: Recv: 250 2.0.0 *************** Message accepted for delivery
DEBUG: Send: QUIT

DEBUG: Recv: 221 2.0.0 ***.***.***.*** closing connection
CentOSの方はこれで解決したのですが、スクリプトを書いているWindowsマシンでは、Net_SMTPを1.7.1にあげてもメールが送信できませんでした。
ファイアウォールを無効にしたらメールを送れるようになりました。

Net_SMTPは暗号化したメールを送るためにNet_Socketでソケットを生成します。
ソケットの生成部分から先に進めていなかったのでファイアウォールのせいかな…と思ってファイアウォールをとめたらメールを送れるようになりました。

PHPのセッションデータの保存先をmemcachedにする場合の設定について

以下の文書は各ソフトが以下のverのものです。
  • memcached-1.4.15-2.el6.remi.x86_64
  • php55w-pecl-memcache-3.0.8-2.w6.x86_64

実現したいことは以下の通りです。

192.168.0.1と192.168.0.2の両方にPHPのセッションデータを保存して、どちらかが落ちても、どちらに接続してもセッションが保たれるようにしたい。


実現したい理由は以下の通りです。

ErogameScapeのPHPのセッションの保存先は各サーバーのHDDのみでした。
セッションの保存先が各サーバーのHDDのみですと以下の問題を抱えます。
  1. ユーザーさんからのサーバーの接続先を切り替えた場合、切り替え先はユーザーさんのセッション情報を持っていないので、ユーザーさんがログインした状態だった場合にサーバーを切り替えると強制的にログアウトされた状態になる。具体的には長文感想を1時間かけて書いて登録ボタンを押したら、ログイン画面に飛ばされる等の被害がでます。
  2. 高負荷時、または定常的にロードバランスしたい場合、あるユーザーさんが最初に接続したサーバーが192.168.0.1、次に接続した場合は192.168.0.2だった場合、セッションが引き継げないためログアウトした状態になる。
    ※ロードバランスをIPアドレスベースでやればIPアドレスがかわらない限り問題ないじゃないか!と思う方もいらっしゃると思いますが、スマホ等からの接続の場合、接続のたびにIPアドレスがころころかわります。
    結果、1.で書いた具体例が起こる可能性があります。
現用系のサーバーから待機系サーバーに切り替えると各ページのキャッシュがないため2時間ほど高負荷となることが確認されました。この対策として、常にキャッシュを更新し続けるのがベストであると思いました。
常にキャッシュを更新し続けるには、定常的にロードバランスするのが手間がかからないなと思いました。

定常的にロードバランスするため、192.168.0.1と192.168.0.2の両方にPHPのセッションデータを保存することとしました。
 

memcachedのインストールと/etc/php.iniと/etc/php.d/memcache.iniの設定について

以下の文書がよいと思います。

はまったのは
;Redundancy : When enabled the client sends requests to N servers in parallel
;memcache.redundancy=1
;memcache.session_redundancy=2
memcache.session_redundancyを3と設定しないといけないことでした。
 
2のままだと、
session.save_path="tcp://192.168.0.2:11211,tcp://192.168.0.1:11211"
と書いても、192.168.0.1の方にしかセッションデータが記録されません。

ちなみに
session.save_path="tcp://192.168.0.2:11211"
と書くとちゃんと192.168.0.2にセッションデータが書き込まれます。

memcache.session_redundancyのパラメータが追加されたのはphp-pecl-memcacheのVerが3系になってからですので、3系を使う場合は気をつけましょう…

ここらへんは英語になりますが
に書いてあります。
※ぐぐっても私と同じようにはまった日本語の文書が全然なくて(やっぱり3系はbetaだから使われていないのでしょうか…)解決に3時間くらいかかりました…プログラマーに必要な言語は英語だとよく言ったものだと思います…

記事検索