Issue: caching with `CacheMode = "Auto"` expires too soon in MSYS2 and Cygwin

Question

Issue: caching with `CacheMode = "Auto"` expires too soon in MSYS2 and Cygwin

sskras opened this issue 8 months ago · 7 comments

Issue Description

Recently I discovered that process elevation credentials could be cached. I set it to Auto:

CacheMode = "Auto"                                (global)

This works with CMD and PowerShell, but not in a pretty recent MSYS2 and Cygwin.

In both latter environments every subsequent launch of gsudo pops up the UAC window.

I expect the caching to work in MSYS2 and Cygwin too.

Steps to Reproduce

run gsudo config to see that all items are default
run gsudo config CacheMode = "Auto"
run gsudo config to see that CacheMode setting got Auto as the global value
run gsudo fltmc
run gsudo fltmc the 2nd time
in both cases UAC pops up

Screenshots

Here is the result I got by adding --debug:

Each invocation poped up a new CMD window, I managed to capture only the last one.

Logs:

Reconfiguring gsudo:

saukrs@DESKTOP-O7JE7JE ~
$ gsudo config
CacheMode = "Explicit"                            (default)
CacheDuration = "00:05:00"                        (default)
LogLevel = "Info"                                 (default)
NewWindow.Force = "False"                         (default)
NewWindow.CloseBehaviour = "OsDefault"            (default)
Prompt = "$p$e[1;31m# $e[0m"                      (default)
PipedPrompt = "$P# "                              (default)
ForceAttachedConsole = "False"                    (default)
ForcePipedConsole = "False"                       (default)
ForceVTConsole = "False"                          (default)
CopyEnvironmentVariables = "False"                (default)
CopyNetworkShares = "False"                       (default)
PowerShellLoadProfile = "False"                   (default)
SecurityEnforceUacIsolation = "False"             (default)
ExceptionList = "notepad.exe;powershell.exe;whoami.exe;vim.exe;nano.exe;" (default)

saukrs@DESKTOP-O7JE7JE ~
$ gsudo config CacheMode = "Auto"
Info: Config Setting for 'CacheMode' will be set as global system setting.
Info: Global system settings requires elevation. Elevating...
Warning: Enabling the credentials cache is a security risk.
CacheMode = "Auto"

saukrs@DESKTOP-O7JE7JE ~
$ gsudo config
CacheMode = "Auto"                                (global)
CacheDuration = "00:05:00"                        (default)
LogLevel = "Info"                                 (default)
NewWindow.Force = "False"                         (default)
NewWindow.CloseBehaviour = "OsDefault"            (default)
Prompt = "$p$e[1;31m# $e[0m"                      (default)
PipedPrompt = "$P# "                              (default)
ForceAttachedConsole = "False"                    (default)
ForcePipedConsole = "False"                       (default)
ForceVTConsole = "False"                          (default)
CopyEnvironmentVariables = "False"                (default)
CopyNetworkShares = "False"                       (default)
PowerShellLoadProfile = "False"                   (default)
SecurityEnforceUacIsolation = "False"             (default)
ExceptionList = "notepad.exe;powershell.exe;whoami.exe;vim.exe;nano.exe;" (default)

Doing two consecutive runs in ~40 seconds with --debug added:

saukrs@DESKTOP-O7JE7JE ~
$ date; gsudo --debug fltmc
Fri May  3 15:42:08 EEST 2024
Debug: Invoking Shell: Bash
Debug: Command Line: --debug fltmc
Debug: Command to run: D:\cygwin64\bin\bash.exe -c "fltmc"
Debug: Using Console mode TokenSwitch
Debug: Caller PID: 12692
Debug: Caller SID: S-1-5-21-3533002965-4122658273-1040882531-1006
Debug: Elevating process: C:\ProgramData\scoop\apps\gsudo\2.4.4\gsudo.exe --debug gsudoservice 12692 S-1-5-21-3533002965-4122658273-1040882531-1006 All 00:05:00
Debug: Service process started.
Debug: Connected via Named Pipe ProtectedPrefix\Administrators\gsudo_6B99D938783616AA600B80393651400D1B4095C779FE631DB109401F6268C86D.
Debug: Creating target process: D:\cygwin64\bin\bash.exe -c "fltmc"
Debug: Process token successfully substituted.

Filter Name                     Num Instances    Altitude    Frame
------------------------------  -------------  ------------  -----
OpenZFS                                                     <Legacy>
bindflt                                 1       409800         1
storqosflt                              0       244000         1
wcifs                                   0       189900         1
CldFlt                                  1       180451         1
FileCrypt                               0       141100         0
luafv                                   1       135000         0
npsvctrig                               1        46000         0
Wof                                     3        40700         0
FileInfo                                8        40500         0
Debug: Process exited with code 0

saukrs@DESKTOP-O7JE7JE ~
$

saukrs@DESKTOP-O7JE7JE ~
$ date; gsudo --debug fltmc
Fri May  3 15:42:43 EEST 2024
Debug: Invoking Shell: Bash
Debug: Command Line: --debug fltmc
Debug: Command to run: D:\cygwin64\bin\bash.exe -c "fltmc"
Debug: Using Console mode TokenSwitch
Debug: Caller PID: 13052
Debug: Caller SID: S-1-5-21-3533002965-4122658273-1040882531-1006
Debug: Elevating process: C:\ProgramData\scoop\apps\gsudo\2.4.4\gsudo.exe --debug gsudoservice 13052 S-1-5-21-3533002965-4122658273-1040882531-1006 All 00:05:00
Debug: Service process started.
Debug: Connected via Named Pipe ProtectedPrefix\Administrators\gsudo_BDB80A29754FF210411978608DB5DCC61235988FE875FE3D7AC39A3738CEA2D5.
Debug: Creating target process: D:\cygwin64\bin\bash.exe -c "fltmc"
Debug: Process token successfully substituted.

Filter Name                     Num Instances    Altitude    Frame
------------------------------  -------------  ------------  -----
OpenZFS                                                     <Legacy>
bindflt                                 1       409800         1
storqosflt                              0       244000         1
wcifs                                   0       189900         1
CldFlt                                  1       180451         1
FileCrypt                               0       141100         0
luafv                                   1       135000         0
npsvctrig                               1        46000         0
Wof                                     3        40700         0
FileInfo                                8        40500         0
Debug: Process exited with code 0

To compare text output in Cygwin terminal and the CMD debug console I launched gsudo additionally. Otherwise the former (seen in the screenshot) self-desctructs in 15 seconds.

So here are both outputs from the new launch. Cygwin terminal:

saukrs@DESKTOP-O7JE7JE ~
$ date; gsudo --debug fltmc
Fri May  3 16:01:36 EEST 2024
Debug: Invoking Shell: Bash
Debug: Command Line: --debug fltmc
Debug: Command to run: D:\cygwin64\bin\bash.exe -c "fltmc"
Debug: Using Console mode TokenSwitch
Debug: Caller PID: 10192
Debug: Caller SID: S-1-5-21-3533002965-4122658273-1040882531-1006
Debug: Elevating process: C:\ProgramData\scoop\apps\gsudo\2.4.4\gsudo.exe --debug gsudoservice 10192 S-1-5-21-3533002965-4122658273-1040882531-1006 All 00:05:00
Debug: Service process started.
Debug: Connected via Named Pipe ProtectedPrefix\Administrators\gsudo_76AA43327BF0DF98CD377FA67FE444C791387E22F43EA6644BAD622D2D68EE64.
Debug: Creating target process: D:\cygwin64\bin\bash.exe -c "fltmc"
Debug: Process token successfully substituted.

Filter Name                     Num Instances    Altitude    Frame
------------------------------  -------------  ------------  -----
OpenZFS                                                     <Legacy>
bindflt                                 1       409800         1
storqosflt                              0       244000         1
wcifs                                   0       189900         1
CldFlt                                  1       180451         1
FileCrypt                               0       141100         0
luafv                                   1       135000         0
npsvctrig                               1        46000         0
Wof                                     3        40700         0
FileInfo                                8        40500         0
Debug: Process exited with code 0

Debug CMD console:

Debug: Command Line: --debug gsudoservice 10192 S-1-5-21-3533002965-4122658273-1040882531-1006 All 00:05:00
gsudo v2.4.4 (Branch.tags-v2.4.4.Sha.cf887bf98d5d3d90fc1eebc08c7a277afb50cd19)
Copyright(c) 2019-2022 Gerardo Grignoli and GitHub contributors

Caller Pid: 12976
Running as:
  User: DESKTOP-O7JE7JE\saukrs
  Sid: S-1-5-21-3533002965-4122658273-1040882531-1006
  Is Admin: True
  Integrity Level: High (12288)

Credentials Cache:
  Mode: Auto
  Available for this process: False
  Total active cache sessions: 0

Processes attached to the current console:
      PID      PPID Integrity  UserName                  Name
    14268     12976 High       DESKTOP-O7JE7JE\saukrs    C:\ProgramData\scoop\apps\gsudo\2.4.4\gsudo.exe (this gsudo status)

Info: Service started
Debug: Service will shutdown if idle for 00:05:00
Debug: Listening on named pipe ProtectedPrefix\Administrators\gsudo_76AA43327BF0DF98CD377FA67FE444C791387E22F43EA6644BAD622D2D68EE64.
Debug: Access allowed only for ProcessID 10192 and children
Debug: NamedPipeServer listening.
Info: Incoming Connection.
Debug: ElevationRequest length 342
Debug: Process token replaced
Info: Connection Closed.
Debug: NamedPipeServer listening.
Info: Allowed Process (Pid 10192) has exited. Ending cache session.)
Info: Service stopped
Service shutdown. This window will close in 15 seconds

Context:

Windows version:
Win10 21H2 - English (OS Build 19044.3086)
gsudo version:
gsudo v2.4.4 (Branch.tags-v2.4.4.Sha.cf887bf98d5d3d90fc1eebc08c7a277afb50cd19)

tested shell versions,

MSYS2:

$ uname -a
MSYS_NT-10.0-19044 DESKTOP-O7JE7JE 3.4.10.x86_64 2023-12-22 10:06 UTC x86_64 Msys

Cygwin:

saukrs@DESKTOP-O7JE7JE ~
$ uname -a
CYGWIN_NT-10.0-19044 DESKTOP-O7JE7JE 3.4.10-1.x86_64 2023-11-29 12:12 UTC x86_64 Cygwin

Answer 1 · 2024-05-03T13:30:05.000Z

I repeated the debug tracing from CMD with 3 consecutive runs of gsudo:

C:\Users\saukrs> gsudo -k
Info: All credentials cache were invalidated.

First run:

C:\Users\saukrs> gsudo --debug fltmc
Debug: Invoking Shell: Cmd
Debug: Command Line: --debug fltmc
Debug: Command to run: "C:\Windows\system32\fltmc.EXE"
Debug: Using Console mode TokenSwitch
Debug: Caller PID: 4480
Debug: Caller SID: S-1-5-21-3533002965-4122658273-1040882531-1006
Debug: Elevating process: C:\ProgramData\scoop\apps\gsudo\2.4.4\gsudo.exe --debug gsudoservice 4480 S-1-5-21-3533002965-4122658273-1040882531-1006 All 00:05:00
Debug: Service process started.
Debug: Connected via Named Pipe ProtectedPrefix\Administrators\gsudo_843F5F48FDA973F21389B11234EB033B58EA49A490BA043B543AB3F4F9DC018B.
Debug: Creating target process: "C:\Windows\system32\fltmc.EXE"
Debug: Process token successfully substituted.

Filter Name                     Num Instances    Altitude    Frame
------------------------------  -------------  ------------  -----
OpenZFS                                                     <Legacy>
bindflt                                 1       409800         1
storqosflt                              0       244000         1
wcifs                                   0       189900         1
CldFlt                                  1       180451         1
FileCrypt                               0       141100         0
luafv                                   1       135000         0
npsvctrig                               1        46000         0
Wof                                     3        40700         0
FileInfo                                8        40500         0
Debug: Process exited with code 0

Second run:

C:\Users\saukrs> gsudo --debug fltmc
Debug: Invoking Shell: Cmd
Debug: Command Line: --debug fltmc
Debug: Command to run: "C:\Windows\system32\fltmc.EXE"
Debug: Using Console mode TokenSwitch
Debug: Caller PID: 4480
Debug: Connected via Named Pipe ProtectedPrefix\Administrators\gsudo_843F5F48FDA973F21389B11234EB033B58EA49A490BA043B543AB3F4F9DC018B.
Debug: Creating target process: "C:\Windows\system32\fltmc.EXE"
Debug: Process token successfully substituted.

Filter Name                     Num Instances    Altitude    Frame
------------------------------  -------------  ------------  -----
OpenZFS                                                     <Legacy>
bindflt                                 1       409800         1
storqosflt                              0       244000         1
wcifs                                   0       189900         1
CldFlt                                  1       180451         1
FileCrypt                               0       141100         0
luafv                                   1       135000         0
npsvctrig                               1        46000         0
Wof                                     3        40700         0
FileInfo                                8        40500         0
Debug: Process exited with code 0

Third run:

C:\Users\saukrs> gsudo --debug fltmc
Debug: Invoking Shell: Cmd
Debug: Command Line: --debug fltmc
Debug: Command to run: "C:\Windows\system32\fltmc.EXE"
Debug: Using Console mode TokenSwitch
Debug: Caller PID: 4480
Debug: Connected via Named Pipe ProtectedPrefix\Administrators\gsudo_843F5F48FDA973F21389B11234EB033B58EA49A490BA043B543AB3F4F9DC018B.
Debug: Creating target process: "C:\Windows\system32\fltmc.EXE"
Debug: Process token successfully substituted.

Filter Name                     Num Instances    Altitude    Frame
------------------------------  -------------  ------------  -----
OpenZFS                                                     <Legacy>
bindflt                                 1       409800         1
storqosflt                              0       244000         1
wcifs                                   0       189900         1
CldFlt                                  1       180451         1
FileCrypt                               0       141100         0
luafv                                   1       135000         0
npsvctrig                               1        46000         0
Wof                                     3        40700         0
FileInfo                                8        40500         0
Debug: Process exited with code 0

Only the first run pops up the UAC prompt. And only one debug CMD console pops up during the test:

Debug: Command Line: --debug gsudoservice 4480 S-1-5-21-3533002965-4122658273-1040882531-1006 All 00:05:00
gsudo v2.4.4 (Branch.tags-v2.4.4.Sha.cf887bf98d5d3d90fc1eebc08c7a277afb50cd19)
Copyright(c) 2019-2022 Gerardo Grignoli and GitHub contributors

Caller Pid: 4480
Running as:
  User: DESKTOP-O7JE7JE\saukrs
  Sid: S-1-5-21-3533002965-4122658273-1040882531-1006
  Is Admin: True
  Integrity Level: High (12288)

Credentials Cache:
  Mode: Auto
  Available for this process: False
  Total active cache sessions: 0

Processes attached to the current console:
      PID      PPID Integrity  UserName                  Name
    12792     11808 High       DESKTOP-O7JE7JE\saukrs    C:\ProgramData\scoop\apps\gsudo\2.4.4\gsudo.exe (this gsudo status)

Info: Service started
Debug: Service will shutdown if idle for 00:05:00
Debug: Listening on named pipe ProtectedPrefix\Administrators\gsudo_843F5F48FDA973F21389B11234EB033B58EA49A490BA043B543AB3F4F9DC018B.
Debug: Access allowed only for ProcessID 4480 and children
Debug: NamedPipeServer listening.
Info: Incoming Connection.
Debug: ElevationRequest length 330
Debug: Process token replaced
Info: Connection Closed.
Debug: NamedPipeServer listening.
Info: Incoming Connection.
Debug: ElevationRequest length 328
Debug: Process token replaced
Info: Connection Closed.
Debug: NamedPipeServer listening.
Info: Incoming Connection.
Debug: ElevationRequest length 329
Debug: Process token replaced
Info: Connection Closed.
Debug: NamedPipeServer listening.

... which stays quite for a while after I have finished my runs.

Answer 2 · 2024-05-03T14:04:49.000Z

Hi, I'm busy these days with work and life, I'll try to make some progress with limited resources...

gsudo cache typically identifies the invoker process as the cache process root, allowing this caller process to elevate again, and also terminating the cache when this process ends.

MSYS2 has a behavior that confuses gsudo. When you run a windows console app from MSYS, it starts an intermediate/wrapper process. gsudo should identify the wrapper and select not the parent but the grandfather process as the cache root process. This part is failing. This is evident since each screenshot you pasted of gsudo --debug has a different 'Caller PID:' line (which is a bad title, since it's not printing the caller PID, but the CacheableRootProcessId which should be the grandfather in this scenario)

So the offending code is likely here

I would need you to tell me:

how did you installed msys2 / cygwin ( scoop? chocolatey? .msi ? ) This helps me reproduce the issue locally.
can you run gsudo status from cygwin 3 times and paste the results here? that would show the process tree that gsudo receives.

Thank you!

Answer 3 · 2024-05-03T14:08:56.000Z

btw in the mean time you can also do gsudo cache on -p {your console pid} to have a working cache. (also gsudo cache on -p 0 would allow any current-user process to elevate, but this is security promiscous)

Answer 4 · 2024-05-03T15:36:07.000Z

Thanks for all the tips.

I'll try to make some progress with limited resources...

No need for promises and hurrying. I just documented the thing that otherwise would be lost in transit :)

how did you installed msys2 / cygwin ( scoop? chocolatey? .msi ? )

I used scoop for that. IIRC, it was scoop install -g gsudo from the elevated CMD.

can you run gsudo status from cygwin 3 times and paste the results here? that would show the process tree that gsudo receives.

Textual output gsudo status being run 3 times in row:

saukrs@DESKTOP-O7JE7JE ~
$ date; gsudo status
Fri May  3 18:33:26 EEST 2024
Caller Pid: 3660
Running as:
  User: DESKTOP-O7JE7JE\saukrs
  Sid: S-1-5-21-3533002965-4122658273-1040882531-1006
  Is Admin: False
  Integrity Level: Medium (8192)

Credentials Cache:
  Mode: Auto
  Available for this process: False
  Total active cache sessions: 0

Processes attached to the current console:
      PID      PPID Integrity  UserName                  Name
    12320      3660 Medium     DESKTOP-O7JE7JE\saukrs    D:\cygwin64\bin\bash.exe
     2104     12320 Medium     DESKTOP-O7JE7JE\saukrs    C:\ProgramData\scoop\apps\gsudo\2.4.4\gsudo.exe (this gsudo status)

saukrs@DESKTOP-O7JE7JE ~
$ date; gsudo status
Fri May  3 18:33:28 EEST 2024
Caller Pid: 12800
Running as:
  User: DESKTOP-O7JE7JE\saukrs
  Sid: S-1-5-21-3533002965-4122658273-1040882531-1006
  Is Admin: False
  Integrity Level: Medium (8192)

Credentials Cache:
  Mode: Auto
  Available for this process: False
  Total active cache sessions: 0

Processes attached to the current console:
      PID      PPID Integrity  UserName                  Name
    14216     12800 Medium     DESKTOP-O7JE7JE\saukrs    D:\cygwin64\bin\bash.exe
     9692     14216 Medium     DESKTOP-O7JE7JE\saukrs    C:\ProgramData\scoop\apps\gsudo\2.4.4\gsudo.exe (this gsudo status)

saukrs@DESKTOP-O7JE7JE ~
$ date; gsudo status
Fri May  3 18:33:29 EEST 2024
Caller Pid: 12592
Running as:
  User: DESKTOP-O7JE7JE\saukrs
  Sid: S-1-5-21-3533002965-4122658273-1040882531-1006
  Is Admin: False
  Integrity Level: Medium (8192)

Credentials Cache:
  Mode: Auto
  Available for this process: False
  Total active cache sessions: 0

Processes attached to the current console:
      PID      PPID Integrity  UserName                  Name
     2948     12592 Medium     DESKTOP-O7JE7JE\saukrs    D:\cygwin64\bin\bash.exe
    12392      2948 Medium     DESKTOP-O7JE7JE\saukrs    C:\ProgramData\scoop\apps\gsudo\2.4.4\gsudo.exe (this gsudo status)

Answer 5 · 2024-06-07T13:57:09.000Z

Ahh... I forgot I knew the answer to this one...
But I didn't understand why it was working fine on my end, and I incorrectly assumed something changed...

The gsudo bash script, forces a new bash instance to run. In Cygwin, the new bash instance is also a new Windows process, that shows in the process tree, while on WSL the new bash PID is not a Windows PID (so it's "invisible" to gsudo).

And that additional windows pid cache is breaking the cache root process selection: (I'm adding this here for future reference)

The workaround is already explained here: https://gerardog.github.io/gsudo/docs/usage/bash-for-windows
... define this function in your ~/.bashrc

gsudo() { WSLENV=WSL_DISTRO_NAME:USER:$WSLENV MSYS_NO_PATHCONV=1 gsudo.exe "$@"; }

Answer 6 · 2024-06-07T13:59:35.000Z

I may review that code again later and see if I can fix the root selection algorithm.. But If I recall correctly, the problem is that the grandparent process ends immediately by the time gsudo starts., so I can't completely trace our grand-grandparent as the cache root. Will check and let you know

Answer 7 · 2024-06-07T15:03:28.000Z

Thanks for the details and the tip/workaround, @gerardog!

What surprises me is the difference that user observes with the PPID value behavior when adding/removing .exe suffix to the command line. That's quite unexpected.