Skip to content

Conversation

@ZauberNerd
Copy link
Contributor

@ZauberNerd ZauberNerd commented Feb 22, 2022

This PR contains a few fixes and improvements for the new expression evaluator:

  • Adds more debug output about which expression is going to be evaluated
  • Use exported IsTruthy() function from the exprparser package inside EvalBool()
  • Fail act when an expression contains errors and cannot be evaluated

Fixes: #1008
Ref: #971

Errors should always be logged with an error level and not debug level.
Since the error is returned here, it will be logged later as an error.
Presumably this was a leftover from debugging the executor chain in:
PR: nektos#971
@ZauberNerd ZauberNerd requested a review from a team as a code owner February 22, 2022 13:49
@ZauberNerd
Copy link
Contributor Author

@ChristopherHX do you remember why you added this debug log in #971 7dbf3fc#diff-fa62a470d83900f015861d603c59c5e371354fb0cdf36089a274d40ee409029eR139?
Since the error is being returned it will be printed eventually.

@mergify
Copy link
Contributor

mergify bot commented Feb 22, 2022

@ZauberNerd this pull request has failed checks 🛠

@mergify mergify bot added the needs-work Extra attention is needed label Feb 22, 2022
@ChristopherHX
Copy link
Contributor

I restored the function 1:1 as it was prior running steps after job failure

https://github.com/nektos/act/blob/v0.2.25/pkg/common/executor.go#L139

I'm not the original author of this debug print

Since the error is being returned it will be printed eventually.

Yes it will eventually get printed. I think it good for debugging to always print any error of the then executor.

@ZauberNerd
Copy link
Contributor Author

Yes it will eventually get printed. I think it good for debugging to always print any error of the then executor.

In my opinion debug logging should be used to provide more information that otherwise isn't visible in order to be able to understand what is happening.
In this case the error is already being printed, so logging the error into the debug log doesn't make much sense.

Below is the test run of https://github.com/nektos/act/pull/971/files#diff-4526efc54b2af950bff29a71c13adadb9f22132374291f264c843cc3cfd51d21

$ ./dist/local/act -W ./pkg/runner/testdata/non-existent-action/push.yml 
[non-existent-action/nopanic] 🚀  Start image=ghcr.io/catthehacker/ubuntu:act-latest
[non-existent-action/nopanic]   🐳  docker pull image=ghcr.io/catthehacker/ubuntu:act-latest platform= username= forcePull=false
[non-existent-action/nopanic]   🐳  docker create image=ghcr.io/catthehacker/ubuntu:act-latest platform= entrypoint=["/usr/bin/tail" "-f" "/dev/null"] cmd=[]
[non-existent-action/nopanic]   🐳  docker run image=ghcr.io/catthehacker/ubuntu:act-latest platform= entrypoint=["/usr/bin/tail" "-f" "/dev/null"] cmd=[]
[non-existent-action/nopanic]   🐳  docker exec cmd=[mkdir -m 0777 -p /var/run/act] user=root workdir=
[non-existent-action/nopanic] ⭐  Run ./path/to/non-existent-action
[non-existent-action/nopanic]   ❌  Failure - ./path/to/non-existent-action
[non-existent-action/nopanic] file does not exist
Error: Job 'nopanic' failed

@codecov
Copy link

codecov bot commented Feb 22, 2022

Codecov Report

Merging #1009 (4114460) into master (4f8da0a) will increase coverage by 1.04%.
The diff coverage is 81.41%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #1009      +/-   ##
==========================================
+ Coverage   57.50%   58.55%   +1.04%     
==========================================
  Files          32       34       +2     
  Lines        4594     4625      +31     
==========================================
+ Hits         2642     2708      +66     
+ Misses       1729     1690      -39     
- Partials      223      227       +4     
Impacted Files Coverage Δ
pkg/common/executor.go 46.90% <ø> (+0.41%) ⬆️
pkg/model/action.go 0.00% <ø> (ø)
pkg/model/planner.go 50.73% <ø> (+0.32%) ⬆️
pkg/exprparser/interpreter.go 72.79% <66.66%> (-0.61%) ⬇️
pkg/runner/expression.go 89.36% <77.61%> (-1.46%) ⬇️
pkg/runner/runner.go 75.89% <78.00%> (-0.58%) ⬇️
pkg/runner/job_executor.go 81.57% <81.57%> (ø)
pkg/runner/step_context.go 85.71% <83.33%> (+4.08%) ⬆️
pkg/runner/action.go 84.21% <84.21%> (ø)
pkg/runner/run_context.go 79.96% <95.83%> (+0.31%) ⬆️
... and 4 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 7d43396...4114460. Read the comment docs.

@mergify mergify bot removed the needs-work Extra attention is needed label Feb 22, 2022
KnisterPeter
KnisterPeter previously approved these changes Feb 22, 2022
@catthehacker
Copy link
Member

In my opinion debug logging should be used to provide more information that otherwise isn't visible in order to be able to understand what is happening. In this case the error is already being printed, so logging the error into the debug log doesn't make much sense.

you could make it a trace instead debug

EldarKurbanov
EldarKurbanov previously approved these changes Feb 22, 2022
mvrshvl
mvrshvl previously approved these changes Feb 22, 2022
@ZauberNerd
Copy link
Contributor Author

ZauberNerd commented Feb 23, 2022

@ChristopherHX @catthehacker so what's the status here? Should I:

  • restore the old behaviour and log the error as debug?
  • log the error as trace?
  • leave it as is?

In case you'd like to keep a log in the Then executor, I'd probably change the log to include a prefix, such as Error in Then executor: %+v or similar, because @KnisterPeter and me had a hard time figuring out where the log came from.

@catthehacker
Copy link
Member

I don't really have any preference, I'll leave it up to you
Just wanted to give another option due to #928

ChristopherHX
ChristopherHX previously approved these changes Feb 23, 2022
Copy link
Contributor

@ChristopherHX ChristopherHX left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Works: I'm ok with removing the debug print. You won't need to address my review comment, which is just an example ( and a bug in act ) why I prefer to use actions/runner locally.

In a later change, we might want to connect this error to an actual job.

Error:   ❌  Error in if-expression: "if: fromJSON('{}')||github.event.pull_request || !github.event.pull_request
" (Unable to map type 'map[]' to boolean for 'fromJSON('{}')||github.event.pull_request || !github.event.pull_request
')

}
default:
return false, fmt.Errorf("Unable to map return type to boolean for '%s'", expr)
return false, fmt.Errorf("Unable to map type '%t' to boolean for '%s'", evaluated, expr)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I thought the default case is impossible to reach for a conforming evaluator.
Any Object != null => true, except empty string

  • if: github.event.pull_request ( true if PR )
  • if: fromJSON('{}') ( always true )
This weird workflow only fails in act, the last step is expected to run
on:
- push
- pull_request
jobs:
  m:
    runs-on:
    - ubuntu-latest
    steps:
    - run: |
                echo PR!
      shell: bash
      if: |
                github.event.pull_request
    - run: |
                echo Push!
      shell: bash
      if: |
                !github.event.pull_request
    - run: |
                echo empty obj!
      shell: bash
      if: |
                fromJSON('{}')

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch, I'll update the function to handle maps.

We've seen this issue when the env map is not set-up properly,
i.e. when the env map is nil, EvalBool might return nil, which should
be handled as a falsy value.
Stop running the workflow in case an expression cannot be evaluated.

Fixes: nektos#1008
It looks like having an expression inside double quotes inside the
expression syntax is not valid: https://github.com/ZauberNerd/act-test/actions/runs/1881986429
The workflow is not valid. .github/workflows/test.yml (Line: 10, Col: 13): Unexpected symbol: '"endsWith'. Located at position 1 within expression: "endsWith('Hello world', 'ld')"
@ZauberNerd ZauberNerd force-pushed the expression-evaluator-fixes branch from 5cea30c to 60d9ad3 Compare February 23, 2022 14:29
@pull-request-size pull-request-size bot added size/L and removed size/M labels Feb 23, 2022
@ZauberNerd
Copy link
Contributor Author

@ChristopherHX @catthehacker I've updated this PR to use the IsTruthy() function from the exprparser package to turn the evaluated string in EvalBool() into a boolean.
Please have another look.

Copy link
Member

@KnisterPeter KnisterPeter left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice

@cplee
Copy link
Contributor

cplee commented Feb 23, 2022

@ZauberNerd - is this a breaking change? looks like the tests had to be updated from " -> '...any concern with that having impact on users?

@ZauberNerd
Copy link
Contributor Author

@ZauberNerd - is this a breaking change? looks like the tests had to be updated from " -> '...any concern with that having impact on users?

These workflows are invalid according to GitHub and strings can only use single quotes: https://docs.github.com/en/actions/learn-github-actions/expressions#literals

Here's a workflow run of the "issue-597" workflow: https://github.com/ZauberNerd/act-test/actions/runs/1889956547

[Invalid workflow file: .github/workflows/test.yml#L17](https://github.com/ZauberNerd/act-test/actions/runs/1889956547/workflow)
The workflow is not valid. .github/workflows/test.yml (Line: 17, Col: 13): Unexpected symbol: '"endsWith'. Located at position 1 within expression: "endsWith('Hello world', 'ld')"

Also, it doesn't look like they worked on master either, just the error while parsing the if condition didn't lead to a non-zero exit-code:

$ ./dist/local/act -W ./pkg/runner/testdata/issue-597/spelling.yaml 
[issue-597/my_first_job] 🚀  Start image=ghcr.io/catthehacker/ubuntu:act-latest
[issue-597/my_first_job]   🐳  docker pull image=ghcr.io/catthehacker/ubuntu:act-latest platform= username= forcePull=false
[issue-597/my_first_job]   🐳  docker create image=ghcr.io/catthehacker/ubuntu:act-latest platform= entrypoint=["/usr/bin/tail" "-f" "/dev/null"] cmd=[]
[issue-597/my_first_job]   🐳  docker run image=ghcr.io/catthehacker/ubuntu:act-latest platform= entrypoint=["/usr/bin/tail" "-f" "/dev/null"] cmd=[]
[issue-597/my_first_job]   🐳  docker exec cmd=[mkdir -m 0777 -p /var/run/act] user=root workdir=
[issue-597/my_first_job]   ❌  Error in if: expression - My first true step

With these changes it looks like this:

$ ~/act/dist/local/act -W ./issue-597/spelling.yaml 
[issue-597/my_first_job] 🚀  Start image=ghcr.io/catthehacker/ubuntu:act-latest
[issue-597/my_first_job]   🐳  docker pull image=ghcr.io/catthehacker/ubuntu:act-latest platform= username= forcePull=false
[issue-597/my_first_job]   🐳  docker create image=ghcr.io/catthehacker/ubuntu:act-latest platform= entrypoint=["/usr/bin/tail" "-f" "/dev/null"] cmd=[]
[issue-597/my_first_job]   🐳  docker run image=ghcr.io/catthehacker/ubuntu:act-latest platform= entrypoint=["/usr/bin/tail" "-f" "/dev/null"] cmd=[]
[issue-597/my_first_job]   🐳  docker exec cmd=[mkdir -m 0777 -p /var/run/act] user=root workdir=
[issue-597/my_first_job] ⭐  Run My first true step
[issue-597/my_first_job]   ☁  git clone 'https://github.com/actions/hello-world-javascript-action' # ref=main
[issue-597/my_first_job]   🐳  docker cp src=/home/ubuntu/.cache/act/actions-hello-world-javascript-action@main/ dst=/var/run/act/actions/actions-hello-world-javascript-action@main/
[issue-597/my_first_job]   🐳  docker exec cmd=[mkdir -p /var/run/act/actions/actions-hello-world-javascript-action@main/] user= workdir=
[issue-597/my_first_job]   🐳  docker exec cmd=[node /var/run/act/actions/actions-hello-world-javascript-action@main/index.js] user= workdir=
| Hello Renst the Octocat!
[issue-597/my_first_job]   ⚙  ::set-output:: time=22:26:32 GMT+0000 (GMT)
| The event payload: {}
[issue-597/my_first_job]   ✅  Success - My first true step

Copy link
Contributor

@ChristopherHX ChristopherHX left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I also wouldn't classify the test workflow corrections as a breaking change, since it never used to work on github. I even blindly duplicated the invalid if in the composite test, in the past assuming these were valid.
I would say deleting container on workflow failure was a breaking change introduced after 0.2.25, no tests no ci failure.

@cplee
Copy link
Contributor

cplee commented Feb 25, 2022

Thanks @ZauberNerd - solid answer :)

@mergify mergify bot merged commit c24cfc7 into nektos:master Feb 25, 2022
@ZauberNerd ZauberNerd deleted the expression-evaluator-fixes branch March 2, 2022 19:16
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Issue: Error in if expression return code 0.

7 participants