Actions do not stop after action timeout when logging heavily
- Dominant language
- Scala
- Stars
- 6.8k
- Forks
- 1.2k
- Avg merge
- 2d 14h
- Merged PRs (30d)
- 2
Description
## 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: , duration: }, 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);
});
}
```
2. Invoke action with following parameters:
```
{
durationMillis : 120000,
delayMillis: 100
}
```
3. 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.
Contributor guide
Assessment
This issue has not been assessed yet.