backend/execute-code: fixing on-exit/finish handling if process is killed

Author: haraldschilly

src/packages/backend/execute-code.ts

@@ -228,6 +228,7 @@ async function executeCodeNoAggregate(
       const pid: number | undefined = doSpawn(
         { ...opts, origCommand, job_id, job_config },
         async (err, result) => {
+          log.debug("async/doSpawn returned", { err, result });
           try {
             const info: Omit<
               ExecuteCodeOutputAsync,
@@ -282,17 +283,18 @@ function sumChildren(
   procs: Processes,
   children: { [pid: number]: number[] },
   pid: number,
-): { rss: number; pct_cpu: number; cpu_secs: number } {
+): { rss: number; pct_cpu: number; cpu_secs: number } | null {
   const proc = procs[`${pid}`];
   if (proc == null) {
     log.debug(`sumChildren: no process ${pid} in proc`);
-    return { rss: 0, pct_cpu: 0, cpu_secs: 0 };
+    return null;
   }
   let rss = proc.stat.mem.rss;
   let pct_cpu = proc.cpu.pct;
   let cpu_secs = proc.cpu.secs;
   for (const ch of children[pid] ?? []) {
     const sc = sumChildren(procs, children, ch);
+    if (sc == null) return null;
     rss += sc.rss;
     pct_cpu += sc.pct_cpu;
     cpu_secs += sc.cpu_secs;
@@ -358,6 +360,7 @@ function doSpawn(
     if (callback_done) return;
 
     while (true) {
+      if (callback_done) return;
       const { procs } = await monitor.processes(Date.now());
       // reconstruct process tree
       const children: { [pid: number]: number[] } = {};
@@ -367,8 +370,13 @@ function doSpawn(
         children[ppid].push(pid);
       }
       // we only consider those, which are the pid itself or one of its children
-      const { rss, pct_cpu, cpu_secs } = sumChildren(procs, children, pid);
-
+      const sc = sumChildren(procs, children, pid);
+      if (sc == null) {
+        // If the process by PID is no longer known, either the process was killed or there are too many running.
+        // in any case, stop monitoring and do not update any data.
+        return;
+      }
+      const { rss, pct_cpu, cpu_secs } = sc;
       // ?? fallback, in case the cache "forgot" about it
       const obj = asyncCache.get(job_id) ?? job_config;
       obj.pid = pid;
@@ -388,8 +396,6 @@ function doSpawn(
       const next_s = Math.max(1, Math.floor(elapsed_s / 6));
       const wait_s = Math.min(next_s, MONITOR_INTERVAL_S);
       await new Promise((done) => setTimeout(done, wait_s * 1000));
-
-      if (callback_done) return;
     }
   }
 
@@ -426,7 +432,9 @@ function doSpawn(
     const obj = asyncCache.get(job_id) ?? opts.job_config;
     if (obj != null) {
       if (aspect === "pid") {
-        if (typeof data === "number") obj.pid = data;
+        if (typeof data === "number") {
+          obj.pid = data;
+        }
       } else if (typeof data === "string") {
         obj[aspect] = data;
       }
@@ -470,7 +478,7 @@ function doSpawn(
   });
 
   child.on("exit", (code) => {
-    exit_code = code != null ? code : undefined;
+    exit_code = code ?? 0;
     finish();
   });
 
@@ -495,8 +503,8 @@ function doSpawn(
 
   const finish = (err?) => {
     if (!killed && (!stdout_is_done || !stderr_is_done || exit_code == null)) {
-      // it wasn't killed and one of stdout, stderr, and exit_code hasn't been
-      // set, so we let the rest of them get set before actually finishing up.
+      // it wasn't killed and none of stdout, stderr, and exit_code hasn't been set.
+      // so we let the rest of them get set before actually finishing up.
       return;
     }
     if (callback_done) {
@@ -510,6 +518,7 @@ function doSpawn(
       clearTimeout(timer);
       timer = undefined;
     }
+
     if (opts.verbose && log.isEnabled("debug")) {
       log.debug(
         "finished exec of",
@@ -524,6 +533,7 @@ function doSpawn(
         exit_code,
       });
     }
+
     if (err) {
       cb(err);
     } else if (opts.err_on_exit && exit_code != 0) {
@@ -588,7 +598,7 @@ function doSpawn(
       } catch (err) {
         // Exceptions can happen, which left uncaught messes up calling code big time.
         if (opts.verbose) {
-          log.debug("r.kill raised an exception", err);
+          log.debug("process.kill raised an exception", err);
         }
       }
       finish(`killed command '${opts.command} ${opts.args?.join(" ")}'`);

src/packages/frontend/frame-editors/latex-editor/actions.ts

@@ -709,39 +709,40 @@ export class Actions extends BaseActions<LatexEditorState> {
     await this.build_action("clean");
   }
 
-  async kill(name: BuildSpecName, job: ExecOutput): Promise<void> {
-    if (job.type !== "async") return;
+  private async kill(job: ExecOutput): Promise<ExecOutput> {
+    if (job.type !== "async") return job;
     const { pid, status } = job;
     if (status === "running" && typeof pid === "number") {
       try {
         // console.log("LatexEditor/actions/kill: killing", pid);
         await exec({
           project_id: this.project_id,
-          command: "kill",
-          args: [`${pid}`],
+          // negative PID, to kill the entire process group
+          command: `kill -9 -${pid}`,
+          // bash: kill + array does not work. IDK why.
+          bash: true,
+          err_on_exit: false,
         });
       } catch (err) {
         // likely "No such process", we just ignore it
-        // console.info("LatexEditor/actions/kill:", err);
+        console.info("LatexEditor/actions/kill:", err);
       } finally {
-        // we keep the data for debugging, but set its state to completed
+        // set this build log to be no longer running
         job.status = "completed";
-        this.set_build_logs({ [name]: job });
       }
     }
+    return job;
   }
 
   // This stops all known jobs with a status "running" and resets the state.
   async stop_build(_id?: string) {
-    const job_infos = this.store.get("build_logs"); //  ("job_infos");
-    if (job_infos) {
-      for (const [name, job] of job_infos) {
-        await this.kill(name, job.toJS());
+    const build_logs = this.store.get("build_logs");
+    if (build_logs) {
+      for (const [name, job] of build_logs) {
+        this.set_build_logs({ [name]: await this.kill(job.toJS()) });
       }
     }
 
-    // this must run in any case, we want a clean empty map!
-    //this.setState({ job_infos: Map() });
     this.set_status("");
     this.is_building = false;
   }
@@ -1344,25 +1345,6 @@ export class Actions extends BaseActions<LatexEditorState> {
     });
   }
 
-  // set_job_infos(obj: {
-  //   [K in keyof IBuildSpecs]?: ExecuteCodeOutputAsync;
-  // }): void {
-  //   let job_infos: JobInfos = this.store.get("job_infos") ?? Map();
-  //   let k: BuildSpecName;
-  //   for (k in obj) {
-  //     const v: ExecuteCodeOutputAsync | undefined = obj[k];
-  //     if (v) {
-  //       job_infos = job_infos.set(
-  //         k as any,
-  //         fromJS(v) as any as TypedMap<ExecOutput>,
-  //       );
-  //     } else {
-  //       job_infos = job_infos.delete(k);
-  //     }
-  //   }
-  //   this.setState({ job_infos });
-  // }
-
   private set_build_logs(obj: { [K in keyof IBuildSpecs]?: BuildLog }): void {
     let build_logs: BuildLogs = this.store.get("build_logs") ?? Map();
     let k: BuildSpecName;

src/packages/frontend/frame-editors/latex-editor/build.tsx

@@ -18,6 +18,10 @@ import Stopwatch from "@cocalc/frontend/editors/stopwatch/stopwatch";
 import { webapp_client } from "@cocalc/frontend/webapp-client";
 import { path_split, tail } from "@cocalc/util/misc";
 import { COLORS } from "@cocalc/util/theme";
+import {
+  ExecuteCodeOutput,
+  ExecuteCodeOutputAsync,
+} from "@cocalc/util/types/execute-code";
 import { Actions } from "./actions";
 import { BuildCommand } from "./build-command";
 import { use_build_logs } from "./hooks";
@@ -95,6 +99,20 @@ export const Build: React.FC<Props> = React.memo((props) => {
     });
   }
 
+  function getMaxMem(stats?: ExecuteCodeOutputAsync["stats"]): string {
+    if (Array.isArray(stats) && stats.length > 0) {
+      const max_mem = stats.reduce((cur, val) => {
+        return val.mem_rss > cur ? val.mem_rss : cur;
+      }, 0);
+      // if there is no data (too many processes, etc.) then it is 0.
+      //  That information is misleading and we ignore it
+      if (max_mem > 0) {
+        return ` Memory usage: ${max_mem.toFixed(0)} MB.`;
+      }
+    }
+    return "";
+  }
+
   function render_log(stage: BuildSpecName): AntdTabItem | undefined {
     if (build_logs == null) return;
     const x: BuildLog | undefined = build_logs.get(stage)?.toJS();
@@ -112,16 +130,7 @@ export const Build: React.FC<Props> = React.memo((props) => {
       if (typeof elapsed_s === "number" && elapsed_s > 0) {
         job_info_str = `Build time: ${elapsed_s.toFixed(1)} seconds.`;
       }
-      if (Array.isArray(stats) && stats.length > 0) {
-        const max_mem = stats.reduce((cur, val) => {
-          return val.mem_rss > cur ? val.mem_rss : cur;
-        }, 0);
-        // if there is no data (too many processes, etc.) then it is 0.
-        //  That information is misleading and we ignore it
-        if (max_mem > 0) {
-          job_info_str += ` Memory usage: ${max_mem.toFixed(0)} MB.`;
-        }
-      }
+      job_info_str += getMaxMem(stats);
     }
     const title = BUILD_SPECS[stage].label;
     // highlights tab, if there is at least one parsed error
@@ -191,17 +200,18 @@ export const Build: React.FC<Props> = React.memo((props) => {
     );
   }
 
-  // usually, one job is running at a time – only render this if there is no status
+  // usually, one job is running at a time
   function render_jobs(): Rendered {
     if (!build_logs) return;
     const infos: JSX.Element[] = [];
     let isLongRunning = false;
     let logTail = "";
-    build_logs.forEach((info, key) => {
-      if (!info || info.get("status") !== "running") return;
-      const stats_str = "";
-      const start = info.get("start");
-      logTail = tail(info.get("stdout") ?? "" + info.get("stderr") ?? "", 6);
+    build_logs.forEach((infoI, key) => {
+      const info: ExecuteCodeOutput = infoI?.toJS();
+      if (!info || info.type !== "async" || info.status !== "running") return;
+      const stats_str = getMaxMem(info.stats);
+      const start = info.start;
+      logTail = tail(info.stdout ?? "" + info.stderr ?? "", 6);
       isLongRunning ||=
         typeof start === "number" &&
         webapp_client.server_time() - start > WARN_LONG_RUNNING_S * 1000;
@@ -254,10 +264,17 @@ export const Build: React.FC<Props> = React.memo((props) => {
           </Flex>
         </div>
         <div style={logStyle}>
-          <span style={{ fontWeight: "bold" }}>
+          <div
+            style={{
+              fontWeight: "bold",
+              whiteSpace: "nowrap",
+              overflow: "hidden",
+              textOverflow: "ellipsis",
+            }}
+          >
             {status}
             {"\n"}
-          </span>
+          </div>
           {logTail}
         </div>
       </>

src/packages/frontend/frame-editors/latex-editor/util.ts

@@ -76,25 +76,27 @@ export async function gatherJobInfo(
   job_info: ExecuteCodeOutputAsync,
   set_job_info: (info: ExecuteCodeOutputAsync) => void,
 ): Promise<void> {
+  await new Promise((done) => setTimeout(done, 100));
   let wait_s = 1;
   try {
     while (true) {
-      await new Promise((done) => setTimeout(done, 1000 * wait_s));
       const update = await exec({
         project_id,
         async_get: job_info.job_id,
         async_stats: true,
       });
-      if (update.type === "blocking") {
+      if (update.type !== "async") {
         console.warn("Wrong type returned. The project is too old!");
         return;
       }
       if (update.status === "running") {
+        console.log("gatherJobInfo", update);
         set_job_info(update);
       } else {
         return;
       }
-      wait_s = Math.min(10, wait_s + 1);
+      await new Promise((done) => setTimeout(done, 1000 * wait_s));
+      wait_s = Math.min(5, wait_s + 1);
     }
   } catch {
     return;
@@ -134,19 +136,20 @@ export async function runJob(opts: RunJobOpts): Promise<ExecOutput> {
   const job_info = await exec(job);
 
   if (job_info.type !== "async") {
-    // this is not an async job. This could happen for old projects.
+    // this is not an async job. This happens with "old" projects, not knowing about async_call.
     return job_info;
   }
 
   if (typeof job_info.pid !== "number") {
     throw new Error("Unable to spawn compile job.");
   }
 
-  set_job_info(job_info);
+  // this runs async, until the job is no longer "running"
   gatherJobInfo(project_id, job_info, set_job_info);
 
   while (true) {
     try {
+      // This also returns the result, if the job has already completed.
       const output = await exec({
         project_id,
         async_get: job_info.job_id,
@@ -160,7 +163,7 @@ export async function runJob(opts: RunJobOpts): Promise<ExecOutput> {
       return output;
     } catch (err) {
       if (err === TIMEOUT_CALLING_PROJECT) {
-        // this will be fine, hopefully. We continue trying to get a reply.
+        // This will eventually be fine, hopefully. We continue trying to get a reply.
         await new Promise((done) => setTimeout(done, 100));
       } else {
         throw new Error(