Nature Remo を使ってみてなんとなく分かったこと の続き

はじめに

これはNature Remoのglobal APIを遅延実行したいが為に作成したlambda APIを
AWSらしい形にリファクタリングしてみただけの内容なので、Nature Remoは全く関係ないです。。

リファクタリングした根拠

AWS lambdaがsetTimeoutをしている間は、Lambda自体も終わりに達しない為、要求されたDelay時間が長くなるほど
CPU時間（要は金）も多くなると思われます。なので必要且つ最低限の時間だけ、AWSインフラを借りるために
遅延自体をAWS側に任せられないか。という地味な命題が根拠となってます。
あとは、AWSがサポートするnode.js 8.11だとasyncが使えたので
ついでに、全面的に書き直してます。

構成図　(thanks for www.draw.io)

今回追加/変更したもの

• IFTTTのapplet
• AWS SQS (Amazon Simple Queue Service) : 標準キュー作成
• API Gateway（＋Lambda)の作成。ここで、IFTTTのリクエストをSQSキューに遅延時間指定で貯める
• Remoリクエスト実行用Lambdaの追加。ここで、SQSキューの追加をトリガにRemoAPIを即時実行する
• デバッグ用：アクセスログ解析の為のCloudWatchログストリーム

各修正/作成点

IFTTTのapplet

http.reuqest

Header : application/json
Body : ${body.json}

ちなみにここで、JSONのキーは必ずダブルクォーテーションでくくる
必要があることを学びました。（くくってない場合はHTTP 400が返る）結構はまった

body.json

{
 "correctkey": "name",
 wrongkey:"name"
}

AWS SQS (Amazon Simple Queue Service) : 標準キューの新設

これは、各マニュアルにお任せします。
ただ、lambdaで使う前提の場合、SQSのFIFOキューは使えないようなので、その点だけお気をつけください。

API Gateway（＋Lambda)の作成。

ここで、IFTTTのリクエストをSQSキューに遅延時間指定で貯めます(IFTTTのアプレットって名前なんとかならんもんかね）

当初は、APIキー必須で運用してたけど、IFTTTがHEADERのカスタマイズが出来ないので
無認証で呼び出し可能にしてます。仮に悪用されても、ライトのON,OFFされる程度なのでまぁいいかと。
最悪Remoの電源切ればいいだけだし。

APIGateway.js

const AWS = require("aws-sdk")
const sqs = new AWS.SQS({apiVersion: '2012-11-05'});

exports.handler = async (event) => {
    
    var prms = [];
    var sum = 0;
    console.log("###############################");
    console.log(event);
    var data = event;
    data.forEach((req)=>{
        console.log(req.delayTime);
        sum += req.delayTime;
        console.log(req.order);
        prms.push(delayedQueue(JSON.stringify(req.order),sum));
    });
    var result;
    await Promise.all(prms).then((res)=>{
        console.log("done");
        result = res;
    }).catch((err)=>{
        throw new Error(err);
    });
    return result;
};

function delayedQueue(message,delay)
{
    // delay time を設定してキューに貯める
    var params = {
        QueueUrl : process.env.DELAYEDQUEUE_URL, 
        MessageBody: message,
        DelaySeconds : delay
        //,MessageGroupId : "MGIdelayedfunction"
    };
    console.log(params);
   return sqs.sendMessage(params).promise();
}

ここでは嵌ったのは、

• SQS リクエスト自体に時間がかかるので、lambdaのタイムアウト時間はデフォルトから変える必要がある。
• SQS queueにFIFO Queueは使えない。（前述）
• SQS queueじゃない場合、MessageGroupId は必須ではない。

くらいですかね。ちなみに、一つ目は何気に重要です。
これを変えないとエラーメッセージ自体をLambda側で受け取れませんでした。。

Remoリクエスト実行用Lambdaの追加。ここで、SQSキューの追加をトリガにRemoAPIを即時実行する

delayedlambda.js

exports.delayed = async (event) => {
  console.log("##################");
  console.log(event);
  var irs = await this.getIRData();
  console.log("##################");
  console.log(irs);
  for(var i=0;i<event.Records.length;i++){

    if(event.Records[i].body === "")
      throw new Error("body was null");

    var orderObj = JSON.parse(event.Records[i].body);
    if(!orderObj || orderObj.length === undefined){
      var paramFmt =  ["IR name","signal name"]

      paramFmt = JSON.stringify(paramFmt);
      console.log(event);
      throw new Error(`The format of parameter is should be ${paramFmt}`);
    }

    console.log("#####order #####");
    console.log(event);
    var id = irs[orderObj[0]][orderObj[1]];
    console.log(id);
    var orderObj = urlfactroy("IR",id);
    this.postImpl(orderObj.url,orderObj.data);
  }
  return "success";
};

最後の最後まで苦戦したこと

Lambdaでは、シーケンシャルに送信されているリクエストが
Remoには正しく届かないという事案が多数。。。
でもCroudWatchログを見る限りは正しく遅延実行は出来てるように見える。。

access.log

2018-08-27T14:18:37.942Z	1f4e4859-7215-571e-b274-1ba77869dc1c	##################
2018-08-27T14:18:37.942Z	1f4e4859-7215-571e-b274-1ba77869dc1c	cached
2018-08-27T14:18:37.961Z	1f4e4859-7215-571e-b274-1ba77869dc1c	#####order #####
2018-08-27T14:18:37.961Z	1f4e4859-7215-571e-b274-1ba77869dc1c	https://api.nature.global/1/signals/SIGNALID/send
2018-08-27T14:18:52.983Z	21b1e921-b05c-5d0a-a889-badfbadca975	##################
2018-08-27T14:18:53.001Z	21b1e921-b05c-5d0a-a889-badfbadca975	cached
2018-08-27T14:18:53.182Z	21b1e921-b05c-5d0a-a889-badfbadca975	#####order #####
2018-08-27T14:18:53.183Z	21b1e921-b05c-5d0a-a889-badfbadca975	https://api.nature.global/1/signals/SIGNALID/send

シグナル送信用のLambda自体は、きちんと遅延時間後に呼び出されているにもかかわらず
Remoのシグナルが不規則に呼び出されるという謎の現象に遭遇し、２、３日格闘後
お手上げだ！！と思いながらこの締めくくりを書いてる時に、違和感のある一行を見つけましたよ!!!

delaydlambda.js

exports.delayed = async (event) => {
  for(var i=0;i<event.Records.length;i++){
    //省略
    
    var orderObj = urlfactroy("IR",id);
    this.postImpl(orderObj.url,orderObj.data);  //<--ここ!!
  }
  return "success";
}

async メソッドなのに、POSTリクエストでawaitしていない？
async書き直しを行った際に、postImplもasycメソッドにしたので
ここだけ見ると、即時このdelayed関数は終わる事になります。
そしておそらくここでの問題は、この関数がlambdaのエントリポイントであることに由来していると思われます。

lambdaは関数がresolve（完了）を返したのでpostImplが実行されているにも関わらず（おそらく）lambdaプロセスの終了処理に入ります。
そして、終了処理に間に合ったpostImplによるリクエストは実行されますが、
間に合わなかったリクエストは（おそらく）killされます。
従って何が実行され何が実行されないかは、神のみぞしる実装となってしまっていたようです。
ま、要はバグですね。

バグ修正コード

delaydlambdaKAI.js

exports.delayed = async (event) => {
  for(var i=0;i<event.Records.length;i++){
    //省略
    
    var orderObj = urlfactroy("IR",id);
    await this.postImpl(orderObj.url,orderObj.data);
  }
  return "success";
}

今はおかげで、１秒単位の設定でRemo君もキビキビ反応してくれるようになりました。
async/awaitキーワードは便利だけど、正直使いこなすのは難しいなと思いました。
それにつけても、このバグ。当初はHTTPの遅延かな？と思って、delayの設定時間を延ばして試してた自分が居たのが恥ずかしい。。