OCI Functions のトラブルシューティング

2024年3月15日 16:37

ひょんな事から触れることになった OCI Functions、ゴリゴリのオンプレの仕事をしている身としては右も左も分からない。「見つけたことをメモっておけばきっと誰かの役に立つはず」と根拠のない自信でこの記事を書かせていただいた。

ひとこと

この記事を書き出してから気がついたが、某弊社の方、Oracle Functions のオブザーバビリティという資料をまとめてくださっている。Syslogや標準出力にでるような作りであれば、Function 自身のロギングポリシーを変更してあげれば、それなりに対応できるはずである。そういうわけで、無駄足を踏んだ記録になった。
「遠くまで行くなら皆で行け」とはこういうことである。

問題の内容

レポジトリにある OCI Streams 使う Functions のサンプルを実行しようとして、2 行だけエラーが出て途方に暮れたという状況。充分細かな粒度でメッセージが出ないと全く役に立たない実例。

hisao_tsuj@cloudshell:create-file (us-ashburn-1)$ echo -n '{"name":"file1.txt","bucketName":"hisaotsu-bucket","content":"Sample content for file1"}' | fn invoke DP-APP create-file
Stream Failed
Obj Failed

ログを取ってみよう

DEBUG=1

アプリケーションはビルドしちゃったし、Logging Policyつけてないし、という状態。コマンドをごそごそ探せば変更できるかもだけど、GUIからは簡単にはできなさそうと思っていたので、まずは気楽に設定できそうな物から。

Troubleshooting OCI Functions にいくつかのトラブルシューティング方法がでている。まずは、環境変数に DEBUG=1 をつける方法で実行してみる。

hisao_tsuj@cloudshell:create-file (us-ashburn-1)$ export DEBUG=1
hisao_tsuj@cloudshell:create-file (us-ashburn-1)$ echo -n '{"name":"file1.txt","bucketName":"hisaotsu-bucket","content":"Sample content for file1"}' | fn invoke DP-APP create-file
POST /20181201/functions/ocid1.fnfunc.oc1.iad.aaaaaaaafpfdqba2o6lm5hh22kr5klsh2sata2abrccmposl2xcd6ym773oq/actions/invoke HTTP/1.1
Host: 3g4asq5f65q.us-ashburn-1.functions.oci.oraclecloud.com
User-Agent: Go-http-client/1.1
Content-Length: 88
Content-Type: text/plain
Accept-Encoding: gzip

{"name":"file1.txt","bucketName":"hisaotsu-bucket","content":"Sample content for file1"}
HTTP/1.1 200 OK
Content-Length: 24
Content-Type: text/plain
Date: Fri, 15 Mar 2024 06:31:05 GMT
Fn-Call-Id: 01HS0CX6471BT0Z20ZJ02J7XDF
Fn-Fdk-Version: fdk-java/1.0.130 (jvm=OpenJDK 64-Bit Server VM, jvmv=11.0.11)
Opc-Request-Id: /01HS0CX63S00000000005ESAAB/01HS0CX63S00000000005ESAAC

Stream Failed
Obj Failed
Stream Failed
Obj Failed
hisao_tsuj@cloudshell:create-file (us-ashburn-1)$

使い物にならない（困惑）。

Functionsの起動時のログを有効にする

Functionの起動時のログは、有効になっていないが、Application から作成したApplicationを開くと、Resources の下に、Logs という項目がある。ここから、Function Invocation Logs が無効になっているのを有効にする。
（赤丸の所のスイッチを切り替える）
事前にLog Groupを作成してない場合は、Enable Logの画面で Log Groupを作ることができるので心配ない。

Object Storageのログを取るグループを作っていたので、雑な命名になっているけれども、再度実行すると、失敗した Function のログが取られている。

クリックするとまずはログが表示されない。Explore Log の Filter by time に Todayを入れてみてみよう。

見てみると、Error storing object in bucket or writing stream (404, BucketNotFound, false) Either the bucket nam… と書かれている。
下向きの矢印みたいな物をクリックすると詳細が表示される。
詳細を見ると、namespace か bucket name が誤っているか、権限がないと書かれている。

{
  "datetime": 1710484798761,
  "logContent": {
    "data": {
      "applicationId": "ocid1.fnapp.oc1.iad.aaaaaaaacbbld2gb6gg75xga5l3oe4abmlhj7ypn2acnfumuc3g4asq5f65q",
      "containerId": "01HS0DD2C90000000000000249",
      "functionId": "ocid1.fnfunc.oc1.iad.aaaaaaaafpfdqba2o6lm5hh22kr5klsh2sata2abrccmposl2xcd6ym773oq",
      "message": "Error storing object in bucket or writing to stream (404, BucketNotFound, false) Either the bucket named 'hisaotsu-bucket' does not exist in the namespace 'idzziuwbzsga' or you are not authorized to access it (opc-request-id: iad-1:mLa6onUNC9KhQRRu3W6zqoxOUUhD6pYqOBiHxIF5ZNdoHuoJHKqG0VpSSyE-jrkK)",
      "opcRequestId": "/01HS0DD1DA00000000005EXR8N/01HS0DD1DA00000000005EXR8P",
      "requestId": "/01HS0DD1DA00000000005EXR8N/01HS0DD1DA00000000005EXR8P",
      "src": "STDERR"
    },
    "id": "b120a497-07ff-46ff-a3f6-ee747c42fc33",
    "oracle": {
      "compartmentid": "ocid1.compartment.oc1..<some-uuid-string-here>mc44qq",
      "ingestedtime": "2024-03-15T06:40:00.581Z",
      "loggroupid": "ocid1.loggroup.oc1.iad.amaaaaaa26i4bsyawitxuwgd2hachmgbt63keiahxavngibtw7yb62n5squa",
      "logid": "ocid1.log.oc1.iad.amaaaaaa26i4bsyaqbxyqdrxa2nvxmm4hd2rbq2zpscd3fphx2h5kzkfj2nq",
      "tenantid": "ocid1.tenancy.oc1..<some-uuid-string-here>h5bctsa"
    },
    "source": "DP-APP",
    "specversion": "1.0",
    "subject": "create-file",
    "time": "2024-03-15T06:39:58.761Z",
    "type": "com.oraclecloud.functions.application.functioninvoke"
  },
  "regionId": "us-ashburn-1"
}

確認してみよう。
このサンプルアプリケーションは、環境変数として、NAMESPACEにNamespaceを設定する。ログから、"NAMESPACE: idzziuwbzsga"と認識していることがわかっている。同様に、JSON の形で、bucketName を渡しているので、このあたりにミスがあれば、異常終了しそうだ。

> oci os ns get --compartment-id ocid1.compartment.oc1..<some-uuid-string-here>mc44qq               
{
  "data": "idzziuwbzsga"
}

$ oci os bucket list --compartment-id ocid1.compartment.oc1..<some-uuid-string-here>mc44qq --namespace-name idzziuwbzsga
{
  "data": [
    {
      "compartment-id": "ocid1.compartment.oc1..aaaaaaaahxv63qxcjjnulqdw2vylk52siwm7v3tfwb2iddkq5wmz32mc44qq",
      "created-by": "ocid1.user.oc1..aaaaaaaahz3tlilznqfmckqfcrg7zunu5cdk4kqanqqukxekvftgzh4zbbqa",
      "defined-tags": null,
      "etag": "0bc3e20b-9929-428e-a2b6-2c3134e743df",
      "freeform-tags": null,
      "name": "hisaotsu-bucket",
      "namespace": "idzziuwbzsga",
      "time-created": "2024-03-13T02:35:57.460000+00:00"
    }
  ]
}

確認してみると、Bucketの名称も、Namespaceも合っている。

そもそも以下のメッセージは、サンプルのJavaのコードの中で、出力された物だ。

"Error storing object in bucket or writing to stream 
(404, BucketNotFound, false) Either the bucket named 'hisaotsu-bucket' 
does not exist in the namespace 'idzziuwbzsga' or you are not authorized 
to access it (opc-request-id: 
iad-1:mLa6onUNC9KhQRRu3W6zqoxOUUhD6pYqOBiHxIF5ZNdoHuoJHKqG0VpSSyE-jrkK)"

問題のコードを一部だけ引用しておくと、try 句の中の catch の部分なので、try の部分で呼び出している関数がこければ、ここに落ちてきてしまう。権限は充分あるので、ソースコードに手を加えて、デバッグをしていくことになる。

    public String handle(ObjectInfo objectInfo) {
(.....)
          try {

              String nameSpace = System.getenv().get("NAMESPACE");
(.....)

          } catch (Throwable e) {
              // ...otherwise, create an error message
              System.err.println("Error storing object in bucket or writing to stream " + e.getMessage());
              result = "Error storing object in bucket or writing to stream " + e.getMessage();
          }

本記事が何らかのお役に立てれば幸いです。

その後の顛末

その後ソースコードに手を加え、どの様な値が渡っているかなどを調べてみた。オブジェクトストレージの namespace、bucket、そして、Stream のエンドポイントなどすべて正しかった。

そこで、手作業でオブジェクトストレージにファイルを作成してみた。

hisao_tsuj@cloudshell:~ (us-ashburn-1)$ cp testfile.txt mytestfile.txt
hisao_tsuj@cloudshell:~ (us-ashburn-1)$ oci os object put --bucket-name hisaotsu-bucket --file ./mytestfile.txt 
Uploading object  [####################################]  100%
{
  "etag": "be7eb8f7-aac4-4211-a2be-0c11eb057734",
  "last-modified": "Thu, 21 Mar 2024 07:39:02 GMT",
  "opc-content-md5": "LSghAvpnElYyfUdn7CO8aw=="
}
hisao_tsuj@cloudshell:~ (us-ashburn-1)$

Administratorのグループに属するユーザーなので、正常に作成される。
うまくいっていないケースとは差異があるはずなので、オブジェクトストレージのサービスログを有効にして調べてみた。例では読み書き両方有効にしてあるが、PUTリクエストなので、Write Access Events だけを有効にすれば十分と思われる。

それぞれのログを比較すると、色々違いはあるが、authentication type と credential、message が異なる。(credential はあえて外してある）

(base) htsujimu@htsujimu-mac temp % diff failed-log.txt upload-log.txt | egrep 'auth|messag'
<       "authenticationType": "resource",
>       "authenticationType": "user",
<       "message": "BucketNotFound",
>       "message": "Object uploaded.",

コードを実行した場合は、authenticationType は resource になる。credential も異なることから異なるユーザーでアクセスしていることが明確になった。（よく考えればあたりまえなのだが。）

そこで、compartment の policy を見てみると、Administrator のグループ以外には権限を付与していなかった。object-family (object storage) と stream-family (Streaming) の権限を付与してあげると、無事正常終了した。

参考文献

Troubleshooting OCI Functions

また、以下の文書も合わせてご覧下さい。

Oracle Functions のオブザーバビリティ

改版の履歴

2024-03-21 その後のデバッグのステップを追加

この記事はここまでです。最後まで読んでいただいてありがとうございます。気に入っていただいたなら、スキを押していただいたり、共有していただけるとうれしいです。コメントや感想大歓迎です！