保存ボタンのハンドラが多重起動し異常中断の 回避方法 伺い

何を実現したいのかを書きましょう

kintoneの編集画面に表示する”関連レコード作成”ボタンのハンドラを作った時は、数分程度の走行時間の処理は実行できたのですが、その”関連レコード作成”を押し忘れて、関連レコードが不揃いになる操作性上の問題がありました。

そこで、保存ボタンのハンドラで、数分程度の走行時間の処理を行おうとした処、動作が不安定になりました。

その動作不正が起きる条件を究明する為に、後述の”問題再現コード”を作成し、問題現象を再現できました。

後述の”問題再現コード”を安定動作できるようにするには、どのように変更すれば良いでしょうか?

発生した問題やエラーメッセージを具体的に書きましょう

  • 保存ボタンを31秒間 連打すると、submitハンドラが多重に起動され、下記のエラーメッセが出て、異常中断します。
ID1002④-3 NG:kintone.app.record.get()実行でエラー、同時実行数=1 
Error: You cannot call kintone.app.record.get() 
in handler or during processing a handler.
  • submitハンドラが2重に起動され、submitハンドラの遅延処理部が実行中の期間に、submit.sucessハンドラは1回だけ起動されますが、下記メッセージが出て、異常中断します。
 sucessイベントハンドラ 処理ID1003: 異常中断 error= 
Error: You cannot call kintone.app.record.get()
 in handler or during processing a handler.
  • 当該submitハンドラは、条件付きでevent.errorにエラーメッセージを入れていて、編集画面に留まる場合もありますが、上述のエラーメッセージが出て、編集画面に留まった場合は、もう保存ボタンを押しても、キャンセルボタンを押しても、無反応になり、一覧画面へのリンクなどをクリックして、画面遷移しないと、復旧できなくなる場合もあります。

<問題再現用JavaScriptプラグインのコード>

下記のプラグインコードは、特定のアプリにしか無いフィールドは参照せず、kintoneアプリに共通な$revisionフィールドしか参照していないので、どのようなkintoneアプリに組み込んでも、保存ボタンを連打すれば、問題現象を再現できます。

// NG_submit_handle3.js
let 処理ID = 1001;
let 同時実行数 = 0;

kintone.events.on([
    "app.record.create.submit",
    "app.record.edit.submit"
], (event) => {
    処理ID += 1;
    同時実行数 += 1;
    console.log(`ID${処理ID}①:二つの非同期処理開始: 同時実行数=${同時実行数}, record1.$revision=${event.record.$revision.value}`, new Date());
    return Promise.all([
        kintone.api.getConcurrencyLimit(),
        new Promise(sucessCallback => {
            const endTime = Date.now() + 31000;
            console.log(`ID${処理ID}②-1:"遅延実行処理 の起動準備`, new Date());
            setTimeout(() => {
                console.log(`ID${処理ID}②-2:"遅延実行処理 始まり`, new Date());
                if (処理ID % 2 === 0) {
                    event.error = `ID${処理ID}②-3:遅延実行処理で、エラー検出`;
                }
                console.log(`ID${処理ID}②-4:"走行時間の長い同期処理 始まり=${curTime = Date.now()}`);
                while (curTime < endTime) { // 31.000秒 - 29.500秒 = 1.5秒間 走行する 同期処理も混在させることにより、保存ボタンやキャンセルボタンの押下が受け付けられなく成りやすくなる
                    curTime = Date.now();
                }
                console.log(`ID${処理ID}②-5:"走行時間の長い同期処理 終わり=${curTime}`);
                sucessCallback(event); // 処理ID③と処理ID⑤の後、再開
                console.log(`ID${処理ID}②-6:遅延実行処理のsucessCallback 呼び出し後, record1.$revision=${event.record.$revision.value}`, new Date());
            }, 29500);
        }),
    ])
        .then(resp2 => {
            console.log(`ID${処理ID}③:"二つの非同期処理結果:`, new Date(), resp2)
            hoge(event.record, 処理ID); // 処理ID ④-1は同期実行だが、④-2以降は、submitハンドラの終了後に 非同期実行されることを、処理IDの順序で確認
            console.log(`ID${処理ID}⑤:after hoge called/ hogeは遅延実行`, new Date())
            同時実行数 -= 1;
            return event;
        });
})

function hoge(record1, processId) {
    console.log(`ID${processId}④-1:hoge entered:同時実行数=${同時実行数} record1.$revision=${record1.$revision.value}`);
    return new Promise(() => {
        setTimeout(() => {
            try {
                const resp4 = kintone.app.record.get();
                console.log(`ID${processId}④-2 ok:ハンドラが終わった頃、同時実行数=${同時実行数}の時、kintone.app.record.get()実行: record4.$revision=${resp4.record.$revision.value} > record1.$revision=${record1.$revision.value}`);
                console.log(`ID${processId}④-3:in hoge normal end:同時実行数=${同時実行数}`, new Date())
            } catch (e) {
                console.warn(`ID${processId}④-3 NG:kintone.app.record.get()実行でエラー、同時実行数=${同時実行数}`, e);
            }
        }, 2000);
    })
}

kintone.events.on([
    "app.record.create.submit.success",
    "app.record.edit.submit.success"
], (event) => {
    try {
        console.log(`sucessイベントハンドラ 処理ID${処理ID}:起動 type=${event.type} ,同時実行数=${同時実行数} `);
        const resp5 = kintone.app.record.get();
        console.log(`sucessイベントハンドラ 処理ID${処理ID}: 正常終了  record5.$revision=${resp5.record.$revision.value}`);
    } catch (err5) {
        console.warn(`sucessイベントハンドラ 処理ID${処理ID}: 異常中断 error=`, err5);

    }
})

** 上記コードのsetTimeoutで、31秒間待っている処理は、本来は、当該レコードのsubTable中のレコードと、別アプリのレコードとを突き合わせて、また別アプリの”関連レコード”を生成してよいか否かを判定する処理で、submitハンドラからreturnした後に遅延処理されるhoge関数部は、”関連レコード”をupsertする処理をしたかった箇所であるなど、もっと 複雑処理で、同程度の走行時間となる処理です。

問題再現コード実行時のconsole.log

ID1002①:二つの非同期処理開始: 同時実行数=1, record1.$revision=8 Tue Nov 26 2024 23:58:47 GMT+0900 (日本標準時)
ID1002②-1:"遅延実行処理 の起動準備 Tue Nov 26 2024 23:58:47 GMT+0900 (日本標準時)
ID1002②-2:"遅延実行処理 始まり Tue Nov 26 2024 23:59:16 GMT+0900 (日本標準時)
ID1002②-4:"走行時間の長い同期処理 始まり=1732633156642
ID1002②-5:"走行時間の長い同期処理 終わり=1732633158139
ID1002②-6:遅延実行処理のsucessCallback 呼び出し後, record1.$revision=8 Tue Nov 26 2024 23:59:18 GMT+0900 (日本標準時)
[Violation]'setTimeout' handler took 1497ms
ID1002③:"二つの非同期処理結果: Tue Nov 26 2024 23:59:18 GMT+0900 (日本標準時) (2) [{…}, {…}]
ID1002④-1:hoge entered:同時実行数=1 record1.$revision=8
ID1002⑤:after hoge called/ hogeは遅延実行 Tue Nov 26 2024 23:59:18 GMT+0900 (日本標準時)
ID1003①:二つの非同期処理開始: 同時実行数=1, record1.$revision=8 Tue Nov 26 2024 23:59:18 GMT+0900 (日本標準時)
ID1003②-1:"遅延実行処理 の起動準備 Tue Nov 26 2024 23:59:18 GMT+0900 (日本標準時)
ID1002④-3 NG:kintone.app.record.get()実行でエラー、同時実行数=1 Error: You cannot call kintone.app.record.get() in handler or during processing a handler.
    at wy (show.js:289:10)
    at Object.get (show.js:1372:72)
ID1003②-2:"遅延実行処理 始まり Tue Nov 26 2024 23:59:47 GMT+0900 (日本標準時)
ID1003②-4:"走行時間の長い同期処理 始まり=1732633187737
ID1003②-5:"走行時間の長い同期処理 終わり=1732633189230
ID1003②-6:遅延実行処理のsucessCallback 呼び出し後, record1.$revision=8 Tue Nov 26 2024 23:59:49 GMT+0900 (日本標準時)
[Violation]'setTimeout' handler took 1493ms
ID1003③:"二つの非同期処理結果: Tue Nov 26 2024 23:59:49 GMT+0900 (日本標準時) (2) [{…}, {…}]
ID1003④-1:hoge entered:同時実行数=1 record1.$revision=8
ID1003⑤:after hoge called/ hogeは遅延実行 Tue Nov 26 2024 23:59:49 GMT+0900 (日本標準時)
 sucessイベントハンドラ 処理ID1003:起動 type=app.record.edit.submit.success ,同時実行数=0 
 sucessイベントハンドラ 処理ID1003: 異常中断 error= Error: You cannot call kintone.app.record.get() in handler or during processing a handler.
    at wy (show.js:289:10)
    at Object.get (show.js:1372:72)
    at :62:42
    at show.js:288:393
    at new bl (show.js:148:333)
ID1003④-2 ok:ハンドラが終わった頃、同時実行数=0の時、kintone.app.record.get()実行: record4.$revision=9 > record1.$revision=8
ID1003④-3:in hoge normal end:同時実行数=0 Tue Nov 26 2024 23:59:51 GMT+0900 (日本標準時)

これまでに、調べたこと

2.1 submitハンドラが多重起動されるのは、kintoneの不具合では無いか?
問題再現コードを組み込んで、保存ボタンを押下すると、約31秒間のほとんどの期間は、保存ボタンは無効化(disable色にはならないが、ボタンに無反応)になっていたので、「submitハンドラは再発火しない」というのが基本的な仕様であるように観えたので、submitハンドラの実行中の何処の瞬間に submitハンドラが再発火してしったことは、kintoneの不具合であろうと、サポート窓口に問い合わせましたが、是非不明な挙動なのだそうです。
<Kintoneのサポータの回答>

恐れ入ります。お問い合わせいただいた内容について、弊社担当部署へ
確認を行ったところ、submitハンドラが再発火できる挙動の是非について、
弊社から案内できる情報がございませんでした。

2.2 submitハンドラで、更新された新しい$revisionのレコードのlookup転記先フィールドやcalcフィールドの値を参照できないなら、submit.sucessハンドラで参照しようとしたが、submitハンドラの処理が終わり切ていない時期にsubmit.sucessハンドラの処理が起動される問題現象が発生し、レコードの値の参照ができなかった。

2.3 submitハンドラの走行期間の条件をサポータに問い合わせたが、有効回答無。
submitハンドラが多重起動できてしまうのは、submitハンドラの走行時間が長くて、保存ボタンを 多重に押下できてしまうことが、きっかけになっているので、「submitハンドラは1495ms以内に 処理終了できなければならない」という制約でもあるのかと思い、Kintoneのサポータに問いあわせてみました。
『サポータとのQ&A
kintone画面のconsoleに出力された
「 [Violation]‘setTimeout’ handler took 1495ms」という警告メッセージが出た意図は、何か禁止事項に触れたことを示唆していますでしょうか?

重ねて恐れ入ります。お知らせいただいたメッセージについては、
「kintone」側で表示しているものではございません。

参考となりますが、弊社でお調べしたところ、当該メッセージは、
処理時間が長い場合に、Webブラウザー側で表示している
警告メッセージのようです。

▼ 参考:Chromeブラウザにおける「Violation」JSアラート
Chromeブラウザにおける「Violation」JSアラート-MYNT Blog
▼ 参考:[Violation] ‘load’ handler took 591msという違反メッセージが
『[Violation] 'load' handler took 591msという違反メッセージが』
※ いずれも弊社ページではございません。ご留意ください。

お手数をおかけしますが、お知らせいただいたメッセージについては、
貴社にてお調べいただき、必要に応じて対処を行うことも、
ご検討いただけますでしょうか。よろしくお願いいたします。
』ここまで、サポータとのQ&A