2019年09月

RTX1210においてL2TP/IPsecを使用したリモートアクセスをした場合のログ

機種 : RTX1210
ファームウェアリビジョン : Rev.14.01.33

接続時
# show log | grep -v "INSPECT"
Searching ...
2019/09/23 08:57:02: [IKE] respond ISAKMP phase to 172.16.0.88
2019/09/23 08:57:02: [IKE] allocated chunk(kind:4 size:335903bytes total:1)
2019/09/23 08:57:02: [IKE] add ISAKMP context [842] 8c40cdce0aeffd63 00000000
2019/09/23 08:57:02: [IKE] invalid ISAKMP proposal
2019/09/23 08:57:02: [IKE] ISAKMP SA attribute (group description) 20
2019/09/23 08:57:02: [IKE] invalid ISAKMP proposal
2019/09/23 08:57:02: [IKE] ISAKMP SA attribute (group description) 19
2019/09/23 08:57:02: [IKE] allocated chunk(kind:2 size:258079bytes total:1)
2019/09/23 08:57:02: [IKE] add ISAKMP SA[1] (gateway[2])
2019/09/23 08:57:02: [IKE] activate ISAKMP socket[2]
2019/09/23 08:57:02: [IKE] respond IPsec phase to 172.16.0.88
2019/09/23 08:57:02: [IKE] add IPsec context [843] 8c40cdce0aeffd63 00000001
2019/09/23 08:57:02: [IKE] not acceptable transform id (0x0b)
2019/09/23 08:57:02: [IKE] setup IPsec SAs (gateway[2], ISAKMP SA[1])
2019/09/23 08:57:02: [IKE] add IPsec SA[2]
2019/09/23 08:57:02: [IKE] add IPsec SA[3]
2019/09/23 08:57:02: [IKE] allocated chunk(kind:3 size:4127bytes total:1)
2019/09/23 08:57:02: [IKE] activate IPsec socket[transport:2](inbound)
2019/09/23 08:57:02: [IKE] activate IPsec socket[transport:2](outbound)
2019/09/23 08:57:02: IP Tunnel[2] Up
2019/09/23 08:57:02: [IKE] IPsec socket[transport:2] is refered
2019/09/23 08:57:02: [L2TP] TUNNEL[2] connected from 172.16.0.88
2019/09/23 08:57:02: [L2TP] TUNNEL[2] tunnel 32943 established
2019/09/23 08:57:03: [L2TP] specific vendor-id: 311
2019/09/23 08:57:03: [L2TP] TUNNEL[2] session 26868 established
2019/09/23 08:57:03: PP[ANONYMOUS01] SEND LCP ConfReq in STARTING
2019/09/23 08:57:03:   ff 03 c0 21 01 01 00 13  01 04 07 00 03 05 c2 23
2019/09/23 08:57:03:   81 05 06 bf 1c 5c 9f
2019/09/23 08:57:03: PP[ANONYMOUS01] RECV LCP ConfReq in REQSENT
2019/09/23 08:57:03:   ff 03 c0 21 01 00 00 15  01 04 05 78 05 06 06 9d
2019/09/23 08:57:03:   60 ba 07 02 08 02 0d 03  06
2019/09/23 08:57:03: PP[ANONYMOUS01] SEND LCP ConfRej in REQSENT
2019/09/23 08:57:03:   ff 03 c0 21 04 00 00 0b  07 02 08 02 0d 03 06
2019/09/23 08:57:03: PP[ANONYMOUS01] RECV LCP ConfAck in REQSENT
2019/09/23 08:57:03:   ff 03 c0 21 02 01 00 13  01 04 07 00 03 05 c2 23
2019/09/23 08:57:03:   81 05 06 bf 1c 5c 9f
2019/09/23 08:57:03: PP[ANONYMOUS01] RECV LCP ConfReq in ACKRCVD
2019/09/23 08:57:03:   ff 03 c0 21 01 01 00 0e  01 04 05 78 05 06 06 9d
2019/09/23 08:57:03:   60 ba
2019/09/23 08:57:03: PP[ANONYMOUS01] SEND LCP ConfAck in ACKRCVD
2019/09/23 08:57:03:   ff 03 c0 21 02 01 00 0e  01 04 05 78 05 06 06 9d
2019/09/23 08:57:03:   60 ba
2019/09/23 08:57:03: PP[ANONYMOUS01] SEND CHAP Challenge in CS_CLOSED/SS_CLOSED
2019/09/23 08:57:03:   ff 03 c2 23 01 01 00 20  10 e4 17 b1 61 3f bf d9
2019/09/23 08:57:03:   54 09 46 ad 17 7e 42 19  52 31 39 32 2e 31 36 38
2019/09/23 08:57:03:   2e 30 2e 31
2019/09/23 08:57:03: PP[ANONYMOUS01] RECV LCP Unknown in OPENED
2019/09/23 08:57:03:   ff 03 c0 21 0c 02 00 12  06 9d 60 ba 4d 53 52 41
2019/09/23 08:57:03:   53 56 35 2e 32 30
2019/09/23 08:57:03: PP[ANONYMOUS01] SEND LCP CodeRej in OPENED
2019/09/23 08:57:03:   ff 03 c0 21 07 02 00 16  0c 02 00 12 06 9d 60 ba
2019/09/23 08:57:03:   4d 53 52 41 53 56 35 2e  32 30
2019/09/23 08:57:03: PP[ANONYMOUS01] RECV LCP Unknown in OPENED
2019/09/23 08:57:03:   ff 03 c0 21 0c 03 00 1f  06 9d 60 ba 4d 53 52 41
2019/09/23 08:57:03:   53 2d 30 2d 44 45 53 4b  54 4f 50 2d 4d 54 32 32
2019/09/23 08:57:03:   49 44 53
2019/09/23 08:57:03: PP[ANONYMOUS01] SEND LCP CodeRej in OPENED
2019/09/23 08:57:03:   ff 03 c0 21 07 03 00 23  0c 03 00 1f 06 9d 60 ba
2019/09/23 08:57:03:   4d 53 52 41 53 2d 30 2d  44 45 53 4b 54 4f 50 2d
2019/09/23 08:57:03:   4d 54 32 32 49 44 53
2019/09/23 08:57:05: PP[ANONYMOUS01] RECV CHAP Response in CS_CLOSED/SS_INIT-CHAL
2019/09/23 08:57:05:   ff 03 c2 23 02 01 00 39  31 70 82 b8 bc 61 eb 38
2019/09/23 08:57:05:   0c a1 07 eb a4 46 5f 33  9a 00 00 00 00 00 00 00
2019/09/23 08:57:05:   00 9e 7e 00 24 63 41 0e  c1 0c 8c 66 03 04 a9 88
2019/09/23 08:57:05:   ef ae c3 3a 92 5d e3 8c  49 00 61 70 32
2019/09/23 08:57:05: PP[ANONYMOUS01] Call detected from user 'myuser'
2019/09/23 08:57:05: PP[ANONYMOUS01] SEND CHAP Success in CS_CLOSED/SS_INIT-CHAL
2019/09/23 08:57:05:   ff 03 c2 23 03 01 00 2e  53 3d 30 38 33 37 45 41
2019/09/23 08:57:05:   38 31 35 31 45 30 36 42  35 35 32 45 39 44 42 38
2019/09/23 08:57:05:   39 35 38 35 39 42 45 31  36 46 42 38 43 44 44 37
2019/09/23 08:57:05:   34 43
2019/09/23 08:57:05: PP[ANONYMOUS01] SEND IPCP ConfReq in STARTING
2019/09/23 08:57:05:   ff 03 80 21 01 01 00 0a  03 06 00 00 00 00
2019/09/23 08:57:05: PP[ANONYMOUS01] SEND IPV6CP ConfReq in STARTING
2019/09/23 08:57:05:   ff 03 80 57 01 01 00 0e  01 0a 02 a0 de ff fe f4
2019/09/23 08:57:05:   73 9f
2019/09/23 08:57:05: PP[ANONYMOUS01] RECV IPV6CP ConfReq in REQSENT
2019/09/23 08:57:05:   ff 03 80 57 01 05 00 0e  01 0a ec 4d de 5a ef 52
2019/09/23 08:57:05:   7f f7
2019/09/23 08:57:05: PP[ANONYMOUS01] SEND IPV6CP ConfAck in REQSENT
2019/09/23 08:57:05:   ff 03 80 57 02 05 00 0e  01 0a ec 4d de 5a ef 52
2019/09/23 08:57:05:   7f f7
2019/09/23 08:57:05: PP[ANONYMOUS01] RECV CCP ConfReq in CLOSED
2019/09/23 08:57:05:   ff 03 80 fd 01 06 00 0a  12 06 01 00 00 00
2019/09/23 08:57:05: PP[ANONYMOUS01] SEND CCP TermAck in CLOSED
2019/09/23 08:57:05:   ff 03 80 fd 06 06 00 04
2019/09/23 08:57:05: PP[ANONYMOUS01] RECV IPCP ConfReq in REQSENT
2019/09/23 08:57:05:   ff 03 80 21 01 07 00 22  03 06 00 00 00 00 81 06
2019/09/23 08:57:05:   00 00 00 00 82 06 00 00  00 00 83 06 00 00 00 00
2019/09/23 08:57:05:   84 06 00 00 00 00
2019/09/23 08:57:05: PP[ANONYMOUS01] SEND IPCP ConfRej in REQSENT
2019/09/23 08:57:05:   ff 03 80 21 04 07 00 16  82 06 00 00 00 00 83 06
2019/09/23 08:57:05:   00 00 00 00 84 06 00 00  00 00
2019/09/23 08:57:05: PP[ANONYMOUS01] RECV IPCP ConfRej in REQSENT
2019/09/23 08:57:05:   ff 03 80 21 04 01 00 0a  03 06 00 00 00 00
2019/09/23 08:57:05: PP[ANONYMOUS01] SEND IPCP ConfReq in REQSENT
2019/09/23 08:57:05:   ff 03 80 21 01 02 00 0a  03 06 c0 a8 00 01
2019/09/23 08:57:05: PP[ANONYMOUS01] RECV IPV6CP ConfAck in ACKSENT
2019/09/23 08:57:05:   ff 03 80 57 02 01 00 0e  01 0a 02 a0 de ff fe f4
2019/09/23 08:57:05:   73 9f
2019/09/23 08:57:05: PP[ANONYMOUS01] PPP/IPV6CP up
2019/09/23 08:57:05: PP[ANONYMOUS01] Local  PP Interface-ID 02a0defffef4739f
2019/09/23 08:57:05: PP[ANONYMOUS01] Remote PP Interface-ID ec4dde5aef527ff7
2019/09/23 08:57:05: PP[ANONYMOUS01] RECV IPCP ConfReq in REQSENT
2019/09/23 08:57:05:   ff 03 80 21 01 08 00 10  03 06 00 00 00 00 81 06
2019/09/23 08:57:05:   00 00 00 00
2019/09/23 08:57:05: PP[ANONYMOUS01] SEND IPCP ConfNak in REQSENT
2019/09/23 08:57:05:   ff 03 80 21 03 08 00 10  03 06 c0 a8 00 35 81 06
2019/09/23 08:57:05:   c0 a8 00 01
2019/09/23 08:57:05: PP[ANONYMOUS01] RECV IPCP ConfAck in REQSENT
2019/09/23 08:57:05:   ff 03 80 21 02 02 00 0a  03 06 c0 a8 00 01
2019/09/23 08:57:05: PP[ANONYMOUS01] RECV IPCP ConfReq in ACKRCVD
2019/09/23 08:57:05:   ff 03 80 21 01 09 00 10  03 06 c0 a8 00 35 81 06
2019/09/23 08:57:05:   c0 a8 00 01
2019/09/23 08:57:05: PP[ANONYMOUS01] SEND IPCP ConfAck in ACKRCVD
2019/09/23 08:57:05:   ff 03 80 21 02 09 00 10  03 06 c0 a8 00 35 81 06
2019/09/23 08:57:05:   c0 a8 00 01
2019/09/23 08:57:05: PP[ANONYMOUS01] PPP/IPCP up  (Local: 192.168.0.1, Remote: 192.168.0.53)
2019/09/23 08:57:05: PP[ANONYMOUS01] Local  PP IP address 192.168.0.1
2019/09/23 08:57:05: PP[ANONYMOUS01] Remote PP IP address 192.168.0.53
2019/09/23 08:57:07: PP[ANONYMOUS01] RECV CCP ConfReq in CLOSED
2019/09/23 08:57:07:   ff 03 80 fd 01 0a 00 0a  12 06 01 00 00 00
2019/09/23 08:57:07: PP[ANONYMOUS01] SEND CCP TermAck in CLOSED
2019/09/23 08:57:07:   ff 03 80 fd 06 0a 00 04
正常終了時(切断ボタンを押下)
2019/09/23 08:58:33: PP[ANONYMOUS01] RECV LCP TermReq in OPENED
2019/09/23 08:58:33:   ff 03 c0 21 05 13 00 10  06 9d 60 ba 00 3c cd 74
2019/09/23 08:58:33:   00 00 00 00
2019/09/23 08:58:33: PP[ANONYMOUS01] SEND LCP TermAck in OPENED
2019/09/23 08:58:33:   ff 03 c0 21 06 13 00 04
2019/09/23 08:58:33: [L2TP] TUNNEL[2] disconnect session 26868 complete
2019/09/23 08:58:33: [L2TP] TUNNEL[2] disconnecting tunnel 32943
2019/09/23 08:58:33: [L2TP] TUNNEL[2] disconnect tunnel 32943 complete
2019/09/23 08:58:33: [IKE] SA[1] change state to OLD
2019/09/23 08:58:33: [IKE] inactivate ISAKMP socket[2]
2019/09/23 08:58:33: [IKE] shutdown tunnel[2]
2019/09/23 08:58:33: [IKE] SA[3] change state to DEAD
2019/09/23 08:58:33: [IKE] initiate informational exchange (delete)
2019/09/23 08:58:33: [IKE] SA[2] change state to DEAD
2019/09/23 08:58:33: [IKE] initiate informational exchange (delete)
2019/09/23 08:58:33: [IKE] inactivate IPsec socket[transport:2](outbound)
2019/09/23 08:58:33: [IKE] delete SA[2]
2019/09/23 08:58:33: [IKE] released chunk(kind:3 size:4127bytes total:0)
2019/09/23 08:58:33: [IKE] inactivate IPsec socket[transport:2](inbound)
2019/09/23 08:58:33: [IKE] delete SA[3]
2019/09/23 08:58:33: IP Tunnel[2] Down
2019/09/23 08:58:33: [IKE] delete request from 172.16.0.88 (SPI: b47d51cc), SA ID: no such SA
2019/09/23 08:58:33: [IKE] delete request from 172.16.0.88 (SPI: 8c40cdce0aeffd63badc6057fa961f67), SA ID: 1
ネットワーク切断(ノートパソコンを閉じた場合)
2019/09/23 09:03:31: [L2TP] TUNNEL[2] disconnect session 12332 complete
2019/09/23 09:03:31: [L2TP] TUNNEL[2] disconnecting tunnel 44734
2019/09/23 09:03:31: [L2TP] TUNNEL[2] disconnect tunnel 44734 complete
2019/09/23 09:03:31: [IKE] SA[1] change state to OLD
2019/09/23 09:03:31: [IKE] inactivate ISAKMP socket[2]
2019/09/23 09:03:31: [IKE] shutdown tunnel[2]
2019/09/23 09:03:31: [IKE] SA[3] change state to DEAD
2019/09/23 09:03:31: [IKE] initiate informational exchange (delete)
2019/09/23 09:03:31: [IKE] SA[2] change state to DEAD
2019/09/23 09:03:31: [IKE] initiate informational exchange (delete)
2019/09/23 09:03:31: [IKE] inactivate IPsec socket[transport:2](outbound)
2019/09/23 09:03:31: [IKE] delete SA[2]
2019/09/23 09:03:31: [IKE] released chunk(kind:3 size:4127bytes total:0)
2019/09/23 09:03:31: [IKE] inactivate IPsec socket[transport:2](inbound)
2019/09/23 09:03:31: [IKE] delete SA[3]
2019/09/23 09:03:31: IP Tunnel[2] Down
2019/09/23 09:03:35: [IKE] SA[1] change state to DEAD
2019/09/23 09:03:35: [IKE] initiate informational exchange (delete)
2019/09/23 09:03:35: [IKE] inactivate ISAKMP socket[2]
2019/09/23 09:03:35: [IKE] delete ISAKMP context [859] ae14a5e34e9c6419 00000000
2019/09/23 09:03:35: [IKE] released chunk(kind:4 size:335903bytes total:0)
2019/09/23 09:03:35: [IKE] delete SA[1]
2019/09/23 09:03:35: [IKE] Reset L2TP/IPsec setting TUNNEL[2]
2019/09/23 09:03:35: [IKE] released chunk(kind:2 size:258079bytes total:0)

double precision型の0.5をroundで四捨五入すると0になる

PostgreSQL11.5の話題です。
double precision型の0.5をroundで四捨五入すると1になって欲しいところ0になります。
ap2=# SELECT round( CAST( 0.5 AS double precision ) ) ;
 round
-------
     0
double precision型はfloat8(倍精度浮動小数点数)なので、誤差が生じるのは分かるのですが…10進数の0.5は2進数で誤差無く表現できると思っているので、なぜroundで四捨五入すると0になるのか分かりませんでした。
ap2=# SELECT round( 0.5 ) AS "round( 0.5 )" , pg_typeof( 0.5 ) AS "pg_typeof( 0.5 )";
-[ RECORD 1 ]----+--------
round( 0.5 )     | 1
pg_typeof( 0.5 ) | numeric
numeric型でしたら、ちゃんと四捨五入して1になるので、numericに型変換すればOKです。
知らずにdouble precision型の数字に対してroundしてしまうこともあるかと思うので、roundするときはとりあえずnumericに型変換しておこうと思いました。

気がついた契機は以下のとおりです。
ErogameScapeでは中央値を計算することが多いのですが、PERCENTILE_CONT関数というとても便利な関数が追加されていたので、SQLを書き換えていました。

gamelistテーブルにはmedianという列があって、ゲームの中央値を格納しています。
このmedidnの列が、どういうわけか…INTEGER型で定義されています(本当に、どういうわけでしょうか…)

あるゲームに62点と63点がつけられた場合、中央値は62.5点になります。
が、medianがINTEGER型になってしまっているので、62.5を四捨五入して63を格納することにしています。

62点と63点の中央値を求めるSQLは以下のとおりです。
ap2=# SELECT PERCENTILE_CONT(0.5) WITHIN GROUP (ORDER BY tokuten) AS "62と63の中央値をPERCENTILE_CONT関数で求める"
ap2-#   FROM (
ap2(#          SELECT 62 AS tokuten
ap2(#           UNION ALL
ap2(#          SELECT 63 AS tokuten
ap2(#        ) AS t
ap2-# ;
-[ RECORD 1 ]-------------------------------+-----
62と63の中央値をPERCENTILE_CONT関数で求める | 62.5
これをroundすると…
ap2=# SELECT round( PERCENTILE_CONT(0.5) WITHIN GROUP (ORDER BY tokuten) ) AS "63になって欲しいけど62になる"
ap2-#   FROM (
ap2(#          SELECT 62 AS tokuten
ap2(#           UNION ALL
ap2(#          SELECT 63 AS tokuten
ap2(#        ) AS t;
-[ RECORD 1 ]----------------+---
63になって欲しいけど62になる | 62
PERCENTILE_CONT(0.5) WITHIN GROUP (ORDER BY tokuten)の戻り値の型を調べると、
ap2=# SELECT pg_typeof(PERCENTILE_CONT(0.5) WITHIN GROUP (ORDER BY tokuten)) AS "戻り値の型はdouble precision"
ap2-#   FROM (
ap2(#          SELECT 62 AS tokuten
ap2(#           UNION ALL
ap2(#          SELECT 63 AS tokuten
ap2(#        ) AS t;
-[ RECORD 1 ]----------------+-----------------
戻り値の型はdouble precision | double precision
double precisionなので、62.5をroundで四捨五入すると62になってしまいます。
そこで、PERCENTILE_CONTの戻り値をnumericに型変換してからroundで四捨五入します。
ap2=# SELECT round( CAST( PERCENTILE_CONT(0.5) WITHIN GROUP (ORDER BY tokuten) AS numeric ) ) AS "numericにCASTしてからなら63になってくれる"
ap2-#   FROM (
ap2(#          SELECT 62 AS tokuten
ap2(#           UNION ALL
ap2(#          SELECT 63 AS tokuten
ap2(#        ) AS t;
-[ RECORD 1 ]-----------------------------+---
numericにCASTしてからなら63になってくれる | 63
double precisionの0.5をroundで四捨五入すると0になる根本理由を知りたいのですが…浮動小数点のことから勉強し直さないと駄目でまったく感覚がなくなっているので…諦めることにしました…

committedが増えていく

ErogameScapeでは各種リソースをmuninで監視しています。
ある日からmemoryのcommittedが着々と増えていきました。
memory
committedがなんなのかをググってもよくわからなかったことと、増えててもサーバーの動作に支障が無いのでそのうち直るかな…と思って放置していました。
メモリを使いそうなのは
  1. PostgreSQL
  2. apache
  3. php
なので、それぞれ再起動してみるもNGでした。
ある日、たまたまスレッド数の画面を見たときに、スレッドも激増していることに気がつきました。
日単位で見ると、ゆるやかに増えているので気がつかなかったのですが、週単位/月単位で見ると激増していることがわかります。
threads
そこでスレッドの状態を確認しました。
# ps_aux_-L

中略

root     27385 27385  0.0    1  0.0 139800   260 ?        S    Sep02   0:00 CROND
ap2      27390 27390  0.0    1  0.0 299400   544 ?        Ss   Sep02   0:00 rsync -aurptz -e /usr/bin/ssh --exclude *~ --delete /home/ap2/public_html ap2@192.168.0.13:/home/ap2
ap2      27395 27395  0.0    1  0.0  60028  1364 ?        S    Sep02   0:00 /usr/bin/ssh -l ap2 192.168.0.13 rsync --server -ulogDtprze.iLs --delete . /home/ap2
root     27464 27464  0.0    1  0.0 139800   628 ?        S    Sep10   0:00 CROND
ap2      27469 27469  0.0    1  0.0 301576  5164 ?        Ss   Sep10   0:00 rsync -aurptz -e /usr/bin/ssh --exclude *~ --delete /home/ap2/public_html ap2@192.168.0.13:/home/ap2
ap2      27473 27473  0.0    1  0.0  60028  2264 ?        S    Sep10   0:00 /usr/bin/ssh -l ap2 192.168.0.13 rsync --server -ulogDtprze.iLs --delete . /home/ap2

以下、いっぱい、繰り返し

中略
ErogameScapeでは、メインのサーバーにスクリプト等をアップロードして、待機系のサーバーにはcronで定期的にrsyncでコピーする、ということをしています。
このrsyncが大量に動いているのか…ゴミとして残っているのか…していました。
手動でrsyncを実行したところ、エラーが滅茶苦茶でて、いっこうにrsyncが終わらないことを確認しました。
rsyncを実行するけど終わらなくて、次のrsyncが実行されて終わらなくて、というのが積み重なっていた模様です。
rsyncを全部殺して、エラーがでないようにrsyncのコマンドを見直して回復しました。 memory2
その後、muninの他のグラフを見たところ、プロセス数も日単位で見るとゆるやかに増えており、週/月単位で見ると激増していたので、閾値をもうけて通知するようにするか、週/月単位のグラフもたまに眺めるようにしないといけないな…と思いました。
processes

記事検索