バッジインポート失敗後に再度試すとすぐに成功する

ties-makimura commented 2 months ago

ログを見ると，issue /api/v1/badge/convert のタイミングで400エラー出ている。

{"log":"{\"level\":\"info\",\"timestamp\":\"2024/8/26 9:24:30\",\"pid\":28,\"hostname\":\"5f0942983078\",\"msg\":\"**************start issue request /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-08-26T00:24:30.968400243Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/8/26 9:24:33\",\"pid\":28,\"hostname\":\"5f0942983078\",\"msg\":\"**************end issue request /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-08-26T00:24:33.086741968Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/8/26 9:24:33\",\"pid\":28,\"hostname\":\"5f0942983078\",\"msg\":\"**************start verify issue request /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-08-26T00:24:33.089873431Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/8/26 9:24:34\",\"pid\":28,\"hostname\":\"5f0942983078\",\"msg\":\"**************end verify issue request /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-08-26T00:24:34.221855474Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/8/26 9:24:34\",\"pid\":28,\"hostname\":\"5f0942983078\",\"msg\":\"**************start issue /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-08-26T00:24:34.22241433Z"}
{"log":"{\"level\":\"warn\",\"timestamp\":\"2024/8/26 9:24:34\",\"pid\":28,\"hostname\":\"5f0942983078\",\"msg\":\"error retryRequest exp: AxiosError: Request failed with status code 400\"}\n","stream":"stdout","time":"2024-08-26T00:24:34.518631937Z"}
{"log":"{\"level\":\"error\",\"timestamp\":\"2024/8/26 9:24:34\",\"pid\":28,\"hostname\":\"5f0942983078\",\"0\":\"Request failed with status code 400\",\"msg\":\"ERROR! /api/v1/badge/convert\"}\n","stream":"stdout","time":"2024-08-26T00:24:34.523959Z"}
・
・
・
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/8/26 9:24:59\",\"pid\":28,\"hostname\":\"5f0942983078\",\"msg\":\"**************start issue request /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-08-26T00:24:59.117971828Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/8/26 9:25:00\",\"pid\":28,\"hostname\":\"5f0942983078\",\"msg\":\"**************end issue request /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-08-26T00:25:00.578030408Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/8/26 9:25:00\",\"pid\":28,\"hostname\":\"5f0942983078\",\"msg\":\"**************start verify issue request /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-08-26T00:25:00.581335616Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/8/26 9:25:01\",\"pid\":28,\"hostname\":\"5f0942983078\",\"msg\":\"**************end verify issue request /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-08-26T00:25:01.697027842Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/8/26 9:25:01\",\"pid\":28,\"hostname\":\"5f0942983078\",\"msg\":\"**************start issue /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-08-26T00:25:01.697571999Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/8/26 9:25:03\",\"pid\":28,\"hostname\":\"5f0942983078\",\"msg\":\"**************end issue /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-08-26T00:25:03.369009374Z"}

期待していた動作

すぐに再トライして成功するようなものは，失敗して欲しくない
リトライ処理に配慮不足な点があれば解消する

スクリーンショット

追記・備考

外部通信するのはバッジインポート以外にもバッジ提出もあるので，必要ならまとめて解消したい
エラーの種類にもよると思うが，再トライすれば成功しそうな場合は，エラーメッセージだけではなく，もう一度お試しください的なメッセージがあれば良いかもしれない

ties-makimura commented 2 months ago

4xx台のステータスコードが返却された場合はリトライしていない？

https://github.com/npocccties/chilowallet/blob/d6a211378f72614fb2e873f52a76b5c0475d71c0/lib/retryRequest.ts#L22-L25

ties-makimura commented 1 month ago

処理中のデータの値をログに出して確認すると，失敗した時は manifest.display.contract の値が空になっていた。 https://github.com/npocccties/chilowallet/blob/d6a211378f72614fb2e873f52a76b5c0475d71c0/server/services/issue.service.ts#L33

成功時ログ

{"level":"info","timestamp":"2024/9/6 18:09:23","pid":29,"hostname":"6623124554e7","msg":"Debug const vcJwt..."}
{"level":"info","timestamp":"2024/9/6 18:09:23","pid":29,"hostname":"6623124554e7","msg":"Debug issue Request Id Token"}
{"level":"info","timestamp":"2024/9/6 18:09:23","pid":29,"hostname":"6623124554e7","0":"https://beta.did.msidentity.com/v1.0/tenants/xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx/verifiableCredentials/issue","msg":"Debug const manifest.input.credentialIssuer"}
{"level":"info","timestamp":"2024/9/6 18:09:23","pid":29,"hostname":"6623124554e7","0":"https://beta.did.msidentity.com/v1.0/tenants/xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx/verifiableCredentials/contracts/yyyyyyyy-yyyy-yyyy-yyyy-yyyyyyyyyyyy/manifest","msg":"Debug const manifest.display.contract"}
{"level":"info","timestamp":"2024/9/6 15:32:15","pid":28,"hostname":"146fea3209fa","msg":"**************end issue /api/v1/badge/convert**************"}

失敗時ログ

{"level":"info","timestamp":"2024/9/6 18:09:23","pid":29,"hostname":"6623124554e7","msg":"Debug const vcJwt..."}
{"level":"info","timestamp":"2024/9/6 18:09:23","pid":29,"hostname":"6623124554e7","msg":"Debug issue Request Id Token"}
{"level":"info","timestamp":"2024/9/6 18:09:23","pid":29,"hostname":"6623124554e7","0":"https://beta.did.msidentity.com/v1.0/tenants/xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx/verifiableCredentials/issue","msg":"Debug const manifest.input.credentialIssuer"}
{"level":"info","timestamp":"2024/9/6 18:09:23","pid":29,"hostname":"6623124554e7","0":"","msg":"Debug const manifest.display.contract"}
{"level":"warn","timestamp":"2024/9/6 15:29:12","pid":28,"hostname":"146fea3209fa","msg":"error retryRequest exp: AxiosError: Request failed with status code 400"}

manifestの値を追うと，manifestToken の時点で，失敗した時は display.contract がなかった https://github.com/npocccties/chilowallet/blob/d6a211378f72614fb2e873f52a76b5c0475d71c0/server/services/manifest.service.ts#L8

対処療法として，getManifest 時に必要な値がなければリトライを加えて様子見る。（最終的にはリトライ部分はリトライ共通化の所に入れた方がよい。） https://github.com/npocccties/chilowallet/commit/684d6b836de0051393ad10ebea609308e942af6b

なお，対処療法を適応した環境でログを見ると，いきなり7回も試行されていた。。様子見てリトライの回数を増やした方がいいかもしれない。

{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:15\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"**************start issue request /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-09-06T09:16:15.932173306Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:18\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"**************end issue request /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-09-06T09:16:18.322587447Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:18\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"**************start verify issue request /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-09-06T09:16:18.326186093Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:18\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Attempting to fetch manifest (Attempt 1/10)\"}\n","stream":"stdout","time":"2024-09-06T09:16:18.874315612Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:19\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Manifest token retrieved successfully\"}\n","stream":"stdout","time":"2024-09-06T09:16:19.258520331Z"}
{"log":"{\"level\":\"error\",\"timestamp\":\"2024/9/6 18:16:19\",\"pid\":28,\"hostname\":\"549b823aa539\",\"0\":{},\"msg\":\"Error fetching manifest on attempt 1:\"}\n","stream":"stdout","time":"2024-09-06T09:16:19.25967699Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:19\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Retrying in 3 seconds...\"}\n","stream":"stdout","time":"2024-09-06T09:16:19.259720106Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:22\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Attempting to fetch manifest (Attempt 2/10)\"}\n","stream":"stdout","time":"2024-09-06T09:16:22.260742315Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:22\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Manifest token retrieved successfully\"}\n","stream":"stdout","time":"2024-09-06T09:16:22.632303329Z"}
{"log":"{\"level\":\"error\",\"timestamp\":\"2024/9/6 18:16:22\",\"pid\":28,\"hostname\":\"549b823aa539\",\"0\":{},\"msg\":\"Error fetching manifest on attempt 2:\"}\n","stream":"stdout","time":"2024-09-06T09:16:22.633352697Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:22\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Retrying in 3 seconds...\"}\n","stream":"stdout","time":"2024-09-06T09:16:22.633388578Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:25\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Attempting to fetch manifest (Attempt 3/10)\"}\n","stream":"stdout","time":"2024-09-06T09:16:25.63700444Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:25\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Manifest token retrieved successfully\"}\n","stream":"stdout","time":"2024-09-06T09:16:25.781848138Z"}
{"log":"{\"level\":\"error\",\"timestamp\":\"2024/9/6 18:16:25\",\"pid\":28,\"hostname\":\"549b823aa539\",\"0\":{},\"msg\":\"Error fetching manifest on attempt 3:\"}\n","stream":"stdout","time":"2024-09-06T09:16:25.782689937Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:25\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Retrying in 3 seconds...\"}\n","stream":"stdout","time":"2024-09-06T09:16:25.782717167Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:28\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Attempting to fetch manifest (Attempt 4/10)\"}\n","stream":"stdout","time":"2024-09-06T09:16:28.784809635Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:28\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Manifest token retrieved successfully\"}\n","stream":"stdout","time":"2024-09-06T09:16:28.93218184Z"}
{"log":"{\"level\":\"error\",\"timestamp\":\"2024/9/6 18:16:28\",\"pid\":28,\"hostname\":\"549b823aa539\",\"0\":{},\"msg\":\"Error fetching manifest on attempt 4:\"}\n","stream":"stdout","time":"2024-09-06T09:16:28.933112359Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:28\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Retrying in 3 seconds...\"}\n","stream":"stdout","time":"2024-09-06T09:16:28.933141483Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:31\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Attempting to fetch manifest (Attempt 5/10)\"}\n","stream":"stdout","time":"2024-09-06T09:16:31.934431805Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:32\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Manifest token retrieved successfully\"}\n","stream":"stdout","time":"2024-09-06T09:16:32.078250975Z"}
{"log":"{\"level\":\"error\",\"timestamp\":\"2024/9/6 18:16:32\",\"pid\":28,\"hostname\":\"549b823aa539\",\"0\":{},\"msg\":\"Error fetching manifest on attempt 5:\"}\n","stream":"stdout","time":"2024-09-06T09:16:32.079180552Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:32\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Retrying in 3 seconds...\"}\n","stream":"stdout","time":"2024-09-06T09:16:32.07921539Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:35\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Attempting to fetch manifest (Attempt 6/10)\"}\n","stream":"stdout","time":"2024-09-06T09:16:35.080238938Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:35\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Manifest token retrieved successfully\"}\n","stream":"stdout","time":"2024-09-06T09:16:35.311306571Z"}
{"log":"{\"level\":\"error\",\"timestamp\":\"2024/9/6 18:16:35\",\"pid\":28,\"hostname\":\"549b823aa539\",\"0\":{},\"msg\":\"Error fetching manifest on attempt 6:\"}\n","stream":"stdout","time":"2024-09-06T09:16:35.312476075Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:35\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Retrying in 3 seconds...\"}\n","stream":"stdout","time":"2024-09-06T09:16:35.312499463Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:38\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Attempting to fetch manifest (Attempt 7/10)\"}\n","stream":"stdout","time":"2024-09-06T09:16:38.314257637Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:38\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Manifest token retrieved successfully\"}\n","stream":"stdout","time":"2024-09-06T09:16:38.63773413Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:38\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"Manifest successfully retrieved and validated\"}\n","stream":"stdout","time":"2024-09-06T09:16:38.639245045Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:38\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"**************end verify issue request /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-09-06T09:16:38.639298771Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:38\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"**************start issue /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-09-06T09:16:38.639305831Z"}
{"log":"{\"level\":\"info\",\"timestamp\":\"2024/9/6 18:16:40\",\"pid\":28,\"hostname\":\"549b823aa539\",\"msg\":\"**************end issue /api/v1/badge/convert**************\"}\n","stream":"stdout","time":"2024-09-06T09:16:40.251851983Z"}

ties-makimura commented 1 month ago

RCOSの段階だと決め打ちでManifest情報取得している？ https://github.com/RCOSDP/credentialwallet_gateway/blob/main/lib/vc.ts#L59-L78

export const getManifestURL = (id: string): string => {
  console.log("start getManifestURL badgeClass criteria.id=", id);
  switch (id) {
    case "https://www.credly.com/org/project-management-institute/badge/project-management-professional-pmp":
      return "https://verifiedid.did.msidentity.com/v1.0/tenants/516c4fed-1f7f-4b23-b9f3-d80b44a2e5bf/verifiableCredentials/contracts/61ba9848-ccab-a0d5-8242-17348cab3952/manifest";
    case "https://moodle.selmid.me/badges/badgeclass.php?id=1":
      return "https://verifiedid.did.msidentity.com/v1.0/tenants/516c4fed-1f7f-4b23-b9f3-d80b44a2e5bf/verifiableCredentials/contracts/98ae2e87-98d8-30fd-78ad-590ec61e5a6d/manifest";
    case "https://moodle.selmid.me/badges/badgeclass.php?id=2":
      return "https://verifiedid.did.msidentity.com/v1.0/tenants/516c4fed-1f7f-4b23-b9f3-d80b44a2e5bf/verifiableCredentials/contracts/61ba9848-ccab-a0d5-8242-17348cab3952/manifest";
    case "https://moodle.selmid.me/badges/badgeclass.php?id=3":
      return "https://verifiedid.did.msidentity.com/v1.0/tenants/516c4fed-1f7f-4b23-b9f3-d80b44a2e5bf/verifiableCredentials/contracts/61ba9848-ccab-a0d5-8242-17348cab3952/manifest";
    case "https://www.credly.com/org/idpro/badge/idpro-member":
      return "https://beta.did.msidentity.com/v1.0/f88bec5c-c13f-4f27-972f-72540d188693/verifiableCredential/contracts/IDProMember";
    case "https://www.credly.com/org/idpro/badge/cidpro-exam-writer":
      return "https://beta.did.msidentity.com/v1.0/f88bec5c-c13f-4f27-972f-72540d188693/verifiableCredential/contracts/CIDProItemWriter";
    case "https://www.credly.com/org/idpro/badge/cidpro-certified-foundation-level":
    default:
      return "https://verifiedid.did.msidentity.com/v1.0/tenants/516c4fed-1f7f-4b23-b9f3-d80b44a2e5bf/verifiableCredentials/contracts/98ae2e87-98d8-30fd-78ad-590ec61e5a6d/manifest";
  }
};

ties-makimura commented 1 month ago

対処療法として，getManifest 時に必要な値がなければリトライを加えて様子見る。（最終的にはリトライ部分はリトライ共通化の所に入れた方がよい。） https://github.com/npocccties/chilowallet/commit/684d6b836de0051393ad10ebea609308e942af6b

リトライで様子見てたけど，急に何度リトライしてもcontract 取得できなくなった。（リトライしすぎて怒られた？）なので，取得できない場合は決めた値を使うよう追加で対処して，ひとまず進んだ。ここまで来たらリトライは不要かも。 https://github.com/npocccties/chilowallet/commit/480e7e90072e0ac9bd145f907273ab55da31c110

（環境変数を用意してて気づいたけど，既存の vc_manifest_url と取得したい contract の値が同じだった。別途用意しなくてもいいかもしれん）

npocccties / chilowallet