apache/openwhisk

Actions do not stop after action timeout when logging heavily

Open

#4,298 opened on 2019年2月20日

GitHub で見る
 (2 comments) (1 reaction) (1 assignee)Scala (6,777 stars) (1,177 forks)batch import
buggood first issueinvoker

説明

Environment details:

  • docker: version 17.06.2-ce, build cec0b72
  • VMs running in Kubernetes cluster, vagrant not used
  • OS: Ubuntu 16.04.5 LTS
  • uname: Linux kube-dal12-cr31330786032045789210c81e62baef04-w171.cloud.ibm 4.4.0-141-generic #167-Ubuntu SMP Wed Dec 5 10:40:15 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

Problem

If an action logs heavily, the action is not stopped by the action timeout. Instead, it continues running as long as it continues logging.

Steps to reproduce the issue:

  1. create an action that runs for a defined duration and logs heavily during that time, Node.js example:
// Licensed to the Apache Software Foundation (ASF) under one or more contributor
// license agreements; and to You under the Apache License, Version 2.0.

// This action prints log lines for a defined duration.
// The output is throttled by a defined delay between two log lines
// in order to keep the log size small and to stay within the log size limit.

function getArg(value, defaultValue) {
   return value ? value : defaultValue;
}

// input: { delay: <delay in millis>, duration: <duration in millis> }, e.g.
// main( { delayMillis: 100, durationMillis: 10000 } );
function main(args) {

   delayMillis = getArg(args.delayMillis, 100);
   durationMillis = getArg(args.durationMillis, 120000);

   logLines = 0;
   startMillis = new Date();

   timeout = setInterval(function() {
      console.log(`[${ ++logLines }] The quick brown fox jumps over the lazy dog.`);
   }, delayMillis);

   return new Promise(function(resolve, reject) {
      setTimeout(function() {
         clearInterval(timeout);
         message = `hello, I'm back after ${new Date() - startMillis} ms and printed ${logLines} log lines`
         console.log(message)
         resolve({ message: message });
      }, durationMillis);
   });

}

  1. Invoke action with following parameters:
{ 
   durationMillis : 120000,
   delayMillis: 100
}
  1. Observe the log timestamps and verify that the action is not stopped after timeout.

Provide the expected results and outputs:

The action is called with 60s timeout and wants to run for 120s. 
The action should be interrupted after 60s.
The log timestamps should not exceed 60s.

Provide the actual results and outputs:

the error message is correct
{  "error": "The action exceeded its time limits of 60000 milliseconds." }

but the log shows that the action is not interrupted after 60s, the action runs for 120s

    "logs": [
        "2019-02-23T12:10:52.440751429Z stdout: [1] The quick brown fox jumps over the lazy dog.",
        "2019-02-23T12:10:52.540964359Z stdout: [2] The quick brown fox jumps over the lazy dog.",
... etc. ...
        "2019-02-23T12:12:52.52384207Z  stdout: [1199] The quick brown fox jumps over the lazy dog.",
        "2019-02-23T12:12:52.523893758Z stdout: hello, I'm back after 120082 ms and printed 1199 log lines"
    ],

Additional information you deem important:

  • we also tested with larger time differences between action timeout and action runtime duration. The behavior is always the same: the action is not interrupted by the action timeout and runs for the full time.

コントリビューターガイド