AWS
RDS
lambda

AWS Lambda上でサーバ時刻がよくわからないことになって困った話

More than 1 year has passed since last update.

↓の記事を元にElasticSearchにRDSのスロークエリログを取り込もうとしていた時に困ったこと。
http://dev.classmethod.jp/cloud/aws/rds-mysql-slowquerylog-to-es/

RDSのログは仕様上1時間毎にローテーションされ、
slowquery/mysql-slowquery.log.xx
の形で保存されます。
xxの部分は、UTCの時刻でxx時までのログ、という形。
つまるところ、UTCの時刻で0000〜0059までのログだったらxxは1
0100〜0159だったらxxは2、という感じ。
あくまでもUTCの時刻なので、JSTの時刻からは-9時間してやる必要があります。

該当の記事では、サーバ時刻を使用して、その1時間前のログを対象にする、
といった処理にしているのですが、これをそのまま使用したところハマってしまいました。
あれれー、スロークエリ発生させてみたはずなのに入ってたり入ってなかったりするぞー。

何度も同じログを参照している

若干ソースをいじってどのスロークエリログを対象にしているかCloudWatch Logsに吐き出させてみたのですが、なんと何時間か同じログを参照していました。
Scheduled Eventで1時間毎に動かしていたのですが、3時間ぐらいずつ、同じログを見ていた模様。

ソース上では下記のように、pythonのプログラムでサーバ時刻を取得して動的に対象ファイル名を変化させています。
以下は抜粋です。

ソース抜粋
import boto3
import re
import os
import json
from datetime import datetime
from dateutil import tz, zoneinfo
from botocore.awsrequest import AWSRequest
from botocore.auth import SigV4Auth
from botocore.endpoint import PreserveAuthSession
from botocore.credentials import Credentials

R = re.compile(TIME_REGEX)
NOW = datetime.now()
INDEX = INDEX_PREFIX + "-" + datetime.strftime(NOW, "%Y%m%d")
TYPE = RDS_ID
SLOWQUERYLOG_PREFIX = "slowquery/mysql-slowquery.log."

def lambda_handler(event, context):
    client = boto3.client("rds")
    db_files = client.describe_db_log_files(DBInstanceIdentifier=RDS_ID)

    log_filename = SLOWQUERYLOG_PREFIX + str(NOW.hour)

でも、対象ファイルが同じということは、サーバ時刻の取得のところが何かおかしいのかなと思い、
今度はNOWの時刻をCloudWatch Logsに吐き出させてみました。

サーバ時刻が3時間ぐらい変わっていない!

確認したところ、1時間毎に動かしている処理が、3回ずつぐらい全く同じ時刻を出していました。
それも寸分違わず。(すいませんがログはここには貼れません…。)
そりゃ同じログ参照しちゃいますね…。
軽く探してみたものの同現象に遭遇している人はすぐ見つからず。
同じようなことになった方いらっしゃいませんかね?

Lambda上でサーバ時刻を取得してはいけない?

上記のような問題があるために、サーバ時刻を取得して利用しようと思うと想定と違った挙動になってしまいます。
Lambdaはサーバ管理のあたりがブラックボックスなのでこのあたりどうなってるのかよくわかりませんね

とりあえず、ntpサーバから時刻取得

現在時刻を取得して何かに利用する処理を入れたいときは、
ntpサーバから時刻を取得したほうがよさそうです。
そうすると今度はntpサーバからの時刻取得に失敗した際どうするのか、
というのを考慮しなければいけませんが…。

解消方法

(2016/07/14追記)
コメントにてご教示いただいた内容を追記。

どうやらlambda_handlerの中で現在時刻を取得すれば問題なく動きそうです。

それを元に修正するとこんな感じでしょうか。

修正したもの
import boto3
import re
import os
import json
from datetime import datetime
from dateutil import tz, zoneinfo
from botocore.awsrequest import AWSRequest
from botocore.auth import SigV4Auth
from botocore.endpoint import PreserveAuthSession
from botocore.credentials import Credentials

R = re.compile(TIME_REGEX)
INDEX = INDEX_PREFIX + "-" + datetime.strftime(NOW, "%Y%m%d")
TYPE = RDS_ID
SLOWQUERYLOG_PREFIX = "slowquery/mysql-slowquery.log."

def lambda_handler(event, context):
    client = boto3.client("rds")
    db_files = client.describe_db_log_files(DBInstanceIdentifier=RDS_ID)
    NOW = datetime.now()
    log_filename = SLOWQUERYLOG_PREFIX + str(NOW.hour)

試してみて、ntpサーバからの時刻とほぼ同時刻であることを確認しました。