Runner: 2.168.0 does not work, permission issue, 2.165.2 worked fine

[thomasdullien]

Describe the bug
Our CI testing started failing today without any change to our .yml or other setup; the only difference is that the GitHub runner was apparently updated from 2.165.2 (which worked fine) to 2.168.0 (which does not work).

We use the "checkout" v2 action, and this seems to fail. Inspecting the raw logs, we see:

2020-04-07T17:35:08.9585074Z [command]/usr/bin/git log -1
2020-04-07T17:35:08.9627094Z commit df7ef1ee005fead76cadffd594e05915452b3583
2020-04-07T17:35:08.9627421Z Author: XXXXXX YYYYYY <[email protected]>
2020-04-07T17:35:08.9628050Z Date:   Tue Apr 7 10:11:38 2020 -0700
2020-04-07T17:35:08.9628138Z 
2020-04-07T17:35:08.9628245Z     Commit message
2020-04-07T17:35:08.9935859Z ##[error]Access to the path '/home/runner/runners/2.168.0/_diag/pages/2a8aec61-a697-428a-8919-a42ea1742359_02880bdf-4d66-515a-adeb-1569bc940d0f_1.log' is denied.

To Reproduce
Steps to reproduce the behavior:

1. In our case, just creating a pull request that causes the action to run is enough.

Our .yml file looks like this:

(...)
jobs:
  run-unit-tests:
    runs-on: ubuntu-latest
    services:
      clickhouse:
        image: yandex/clickhouse-server
        ports:
          - 9000:9000
        volumes:
          - /:/var/lib/clickhouse
    container:
      image: [some-repository]/[some-image-name]:latest
    steps:
      - name: Checkout code
        uses: actions/checkout@v2
        with:
          path: github.com/optimyze/prodfiler

Expected behavior
Existing .yml files that worked with version 2.165.2 should not break due to Github updating to 2.168.0.

Runner Version and Platform

2.165.2 (working) vs. 2.168.0 (non-working)

The OS is whatever Github actions uses.

What's not working?

The checkout action fails due to a permissions error.

Job Log Output

See above.

Apologies

I am not sure this is the right place to report the issue - if there is a more appropriate venue, please point me to it.

[TingluoHuang]

@thomasdullien can you enable step and runner debug and share log with us?
https://help.github.com/en/actions/configuring-and-managing-workflows/managing-a-workflow-run#enabling-debug-logging

[thomasdullien]

Yes, of course :-)

Do you need the entire log? The relevant section is here:

020-04-07T20:20:12.7095571Z ##[debug]Removed matchers: 'checkout-git'
2020-04-07T20:20:12.7326640Z ##[debug]Node Action run completed with exit code 0
2020-04-07T20:20:12.7330669Z ##[debug]Finishing: Checkout code
2020-04-07T20:20:12.7353394Z ##[error]Access to the path '/home/runner/runners/2.168.0/_diag/pages/a83fe1d4-f1cd-4889-be64-f5cc67ec120d_02880bdf-4d66-515a-adeb-1569bc940d0f_1.log' is denied.
2020-04-07T20:20:12.7358321Z ##[debug]System.UnauthorizedAccessException: Access to the path '/home/runner/runners/2.168.0/_diag/pages/a83fe1d4-f1cd-4889-be64-f5cc67ec120d_02880bdf-4d66-515a-adeb-1569bc940d0f_1.log' is denied.
2020-04-07T20:20:12.7358492Z ##[debug] ---> System.IO.IOException: Permission denied
2020-04-07T20:20:12.7358600Z ##[debug]   --- End of inner exception stack trace ---
2020-04-07T20:20:12.7358722Z ##[debug]   at Interop.ThrowExceptionForIoErrno(ErrorInfo errorInfo, String path, Boolean isDirectory, Func`2 errorRewriter)
2020-04-07T20:20:12.7358852Z ##[debug]   at Microsoft.Win32.SafeHandles.SafeFileHandle.Open(String path, OpenFlags flags, Int32 mode)
2020-04-07T20:20:12.7358978Z ##[debug]   at System.IO.FileStream.OpenHandle(FileMode mode, FileShare share, FileOptions options)
2020-04-07T20:20:12.7359118Z ##[debug]   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options)
2020-04-07T20:20:12.7359240Z ##[debug]   at System.IO.FileStream..ctor(String path, FileMode mode)
2020-04-07T20:20:12.7359349Z ##[debug]   at GitHub.Runner.Common.PagingLogger.NewPage()
2020-04-07T20:20:12.7359672Z ##[debug]   at GitHub.Runner.Common.PagingLogger.Write(String message)
2020-04-07T20:20:12.7359788Z ##[debug]   at GitHub.Runner.Worker.ExecutionContext.Write(String tag, String message)
2020-04-07T20:20:12.7359910Z ##[debug]   at GitHub.Runner.Worker.ExecutionContextExtension.Debug(IExecutionContext context, String message)
2020-04-07T20:20:12.7360028Z ##[debug]   at GitHub.Runner.Worker.StepsRunner.RunAsync(IExecutionContext jobContext)
2020-04-07T20:20:12.7360158Z ##[debug]   at GitHub.Runner.Worker.JobRunner.RunAsync(AgentJobRequestMessage message, CancellationToken jobRequestCancellationToken)
2020-04-07T20:20:12.7364618Z ##[debug]Finishing: run-unit-tests

[TingluoHuang]

@thomasdullien do you mind send the full log to [email protected].
I can see where the problem happen, but not sure why that happen, is your workflow on a public repo that i can access? 😞

[vikmik]

Hey @TingluoHuang , I'll take over from @thomasdullien for this. I'll send you the info via email. Thanks!

[TingluoHuang]

@vikmik cool, let me know when you send the email. 😄

[vikmik]

Sent it just now :)

[vikmik]

It turns out that the following seems to be the culprit:

      clickhouse:
        image: yandex/clickhouse-server
        ports:
          - 9000:9000
        volumes:
          - /:/var/lib/clickhouse

If I change the volume specification to something else (like /tmp:/var/lib/clickhouse), this error disappears. So, maybe we can't use '/' to specify volumes now? As @thomasdullien mentioned, this was working previously

[vikmik]

Note that this can be reproduced without access to our private repo:

name: unit-test-on-pull-request

on:
  push:
    branches: [ master, develop, ci-develop ]
  pull_request:
    branches: [ master, develop, ci-develop ]

jobs:
  run-unit-tests:
    runs-on: ubuntu-latest
    services:
      clickhouse:
        image: yandex/clickhouse-server
        ports:
          - 9000:9000
        volumes:
          - /:/var/lib/clickhouse
    container:
      image: alpine:3.11.5
    steps:
      - name: Checkout code
        uses: actions/checkout@v2
        with:
          path: github.com/actions/runner
      - name: Show the proc directory
        run: cat /proc/1/maps

[vikmik]

Note: we do have a good workaround. I'll still leave this issue open since this is a breaking change and might impact others.

[TingluoHuang]

@vikmik I can't repro the issue with 2.168.0 self-hosted runner locally, looks like it only repros on the hosted runner. 😞
This might indicate something wrong with the hosted environment, like Docker version, etc.
Can you help me check your last successful build and first failed build, and sure the timestamp the run?

[vikmik]

So, our last successful build was at 2020-04-07T14:49:33 UTC
The first one that failed was at 2020-04-07T16:07:55 UTC

However: the first failed build failed because of another reason, which I suppose is related to the same underlying issue.
Apparently we cannot provide non-absolute paths in for volume mounts anymore. Our initial config was specifying /:var/lib/clickhouse for the volume (notice the missing / in front of var/lib). This was working great before, but started failing today as well - this is what started failing at 2020-04-07T16:07:55 UTC. This caused the builds to fail in an earlier step, on the docker create invocation.

Since this was an easy fix, we added a leading '/'. This allowed the builds to go further, but failed on the permission problem.

So, the first build that I can confirm failed for the permission issue was a little later, at 2020-04-07T18:11:42 UTC.
But since it is quite suspicious that our builds first started failing because of non-absolute volume paths, I would suspect you could use 2020-04-07T16:07:55 UTC for your investigation - assuming the 2 errors are related to the same root cause.

[TingluoHuang]

@vikmik I think this might caused by https://github.com/actions/runner/pull/384. We fixed a bug that we never actually use volume from yaml. That's something new in this runner.

Can you check your successful build to see whether we pass the volume mount into docker create like we have now?
2.168.0 Runner:
/usr/bin/docker create --name 1b763ce7f93b427ea93108a48fc9d6e3_yandexclickhouseserver_ae538e --label d00b33 --network github_network_2ebb59e7cf7e43d88b632fdb84726f9c --network-alias clickhouse -p 9000:9000 -e GITHUB_ACTIONS=true -e CI=true -v "/":"/var/lib/clickhouse" yandex/clickhouse-server

[vikmik]

Oh, so you're saying that this would have failed if that line wasn't previously ignored?

Our workaround is actually to remove that volume mount altogether, which wasn't necessary anyway :)
It is pretty confusing to see the build fail with the permission error when we map / to a directory inside the container(/var/lib/clickhouse). But what you're saying is that this issue was probably always there? :)

If this is not supported (mounting /), then it might be good to surface it better. If it's supposed to work, then why did this workflow fail?

Regardless of the answer to this, thanks a lot for the help! We are unblocked. However you may still want to track this issue down if that behavior is unexpected

[TingluoHuang]

@vikmik i think i find the problem.
when you not mounting / the file ownership looks like

/home/runner/runners/2.168.0/_diag:
total 1344
-rw-r--r-- 1 runner docker 1265668 Apr  8 01:21 Runner_20200408-012156-utc.log
-rw-r--r-- 1 runner docker   10147 Apr  8 01:22 Runner_20200408-012254-utc.log
-rw-r--r-- 1 runner docker    1013 Apr  8 01:21 Worker_20200408-012156-utc.log
-rw-r--r-- 1 runner docker   82262 Apr  8 01:23 Worker_20200408-012258-utc.log
drwxr-xr-x 2 runner docker    4096 Apr  8 01:23 pages

when you mounting / the file ownership looks like

/home/runner/runners/2.168.0/_diag:
total 1344
-rw-r--r-- 1 systemd-resolve systemd-journal 1265668 Apr  8 01:41 Runner_20200408-014117-utc.log
-rw-r--r-- 1 systemd-resolve systemd-journal   10147 Apr  8 01:42 Runner_20200408-014241-utc.log
-rw-r--r-- 1 systemd-resolve systemd-journal    1013 Apr  8 01:41 Worker_20200408-014117-utc.log
-rw-r--r-- 1 systemd-resolve systemd-journal   82459 Apr  8 01:43 Worker_20200408-014245-utc.log
drwxr-xr-x 2 systemd-resolve systemd-journal    4096 Apr  8 01:43 pages

since the runner process is running as user runner, when you mount / into container, runner lost permission to everything.

I ran about 10 runs, depends on how fast the VM in the hosted environment, I am hitting the permission problem in different places, some like yours, after the first step finish, the runner can't start the next step, some are the runner even fail to run the first step. I can feel the docker daemon slowly take over the entire file system.

I am going to create a PR in the runner to raise a warning to user if they try to mount the / into container.

[vikmik]

Ok, so since it's the clickhouse image that's doing a chown -R of the volume mount, mounting / was a bad idea on our part. The fact that it was hidden because of https://github.com/actions/runner/pull/384 made us point the finger at you, but really we shouldn't have done that in the first place regardless of that bug in GitHub actions.

I think adding the warning makes sense, but we're totally to blame here :)

So, feel free to close this. Again thanks so much for the quick turnaround & help on this - super appreciated!

[TingluoHuang]

Glad you are unblocked and we understand the root cause, I am going to merge the PR and close this issue. Thanks for reporting this. 👍