Hi folks, I'm running into an error in my metaflow process and need some help to debug it. The code works fine outside of metaflow, but once I try to execute it within a metaflow step it reliably hits a "SIGKILL" message (locally) or exit 137 (on k8s). I get this message even with a massive (>80GB ram) resource allocation or local execution. Locally, I have profiled the code and it's <100MB of usage. Locally, I also don't see any entries in dmesg or system log. My memory usage on my local machine is within normal bounds at the time of the task being killed. This fails reliably in each of two steps: 1. Installing (or re-installing) the R package I am using, which includes compiling a model via cmdstanr. 2. Running (fitting) the model except when I limit to one process (chain) at a time. I have included a reproducible example of the first, and not of the second. I have a way to get around these two limitations (docker image & limiting to single process), but I'd like to be able to relax both. Are there other limits to the virtualenv in which steps run (file size? swap? multi-threading?) that I should be aware of? Any other hints to help debug this further? Here is a reproducible example using a public package (and the same pypi context our package requires). For me, it fails right during the

cmdstanr.install_cmdstan()

line:

from metaflow import FlowSpec, step, pypi#, environment
import os

class MinimumFlow(FlowSpec):
    
    @step
    def start(self):
        self.next(self.install)
    
    # @environment(vars={'GITHUB_PAT': os.getenv('GITHUB_PAT')})
    @pypi(python='3.9.18', packages = {'numpy': '1.26.2', 'pandas': '1.5.3',
                                       'rpy2': '3.5.14', 'cmdstanpy': '1.2.0',
                                       'rpy2-arrow': '0.0.8'})
    @step
    def install(self):
        print("Installing packages")
        from rpy2.robjects.packages import importr
        os.environ['R_REMOTES_STANDALONE'] = "true"
        utils = importr('utils')
        utils.chooseCRANmirror(ind=1)
        print("Installing remotes")
        utils.install_packages('remotes')
        remotes = importr('remotes')
        print("Installing cmdstanr")
        remotes.install_github('stan-dev/cmdstanr', force = True)
        cmdstanr = importr('cmdstanr')
        print("Checking cmdstan requirements")
        cmdstanr.check_cmdstan_toolchain()
        print("Installing cmdstan")
        cmdstanr.install_cmdstan()
        print("Packages installed")
        self.next(self.end)

    @step
    def end(self):
        print("Flow is done!")

if __name__ == "__main__":
    MinimumFlow()

is there anything about OOM kill in pod status in k8s?

Thank you so much for taking a look at this! I'm running into the conda error so I will show here the output not from this minimal example but from a live run.

is there anything about OOM kill in pod status in k8s?

Not that I can find, but it's possible I am missing where to look. The relevant part of the

describe

output:

State:          Terminated
      Reason:       Error
      Exit Code:    137
      Started:      Tue, 19 Dec 2023 18:06:01 -0500
      Finished:     Tue, 19 Dec 2023 18:06:14 -0500
    Ready:          False
    Restart Count:  0
    Limits:
      <http://nvidia.com/gpu|nvidia.com/gpu>:  0
    Requests:
      cpu:                5
      ephemeral-storage:  10240M
      memory:             48G
      <http://nvidia.com/gpu|nvidia.com/gpu>:     0

In the events, I don't see that much of interest in the

argo

namespace:

m41s       Normal    SuccessfulCreate       Job/t-bc04f3b3-f66qf         Created pod: t-bc04f3b3-f66qf-6xfrq
8m40s       Normal    Pulled                 Pod/t-bc04f3b3-f66qf-6xfrq   Successfully pulled image "xxxx" in 712.62461ms (712.640234ms including waiting)
8m40s       Normal    Created                Pod/t-bc04f3b3-f66qf-6xfrq   Created container sample-posterior
8m40s       Normal    Started                Pod/t-bc04f3b3-f66qf-6xfrq   Started container sample-posterior
8m24s       Warning   BackoffLimitExceeded   Job/t-bc04f3b3-f66qf         Job has reached the specified backoff limit

However, possibly relevant entries in the default namespace:

LAST SEEN                TYPE      REASON             OBJECT                                                     MESSAGE
34m (x24 over 5d18h)     Warning   NodeSysctlChange   Node/gke-gke-metaflow-defau-highcpu-pool-2-49461fa8-nlrp   {"unmanaged": {"net.netfilter.nf_conntrack_buckets": "491520"}}
104s (x1488 over 6d4h)   Warning   FailedCreate       Job/t-b1ea2d75-qgtfw                                       Error creating: pods "t-b1ea2d75-qgtfw-" is forbidden: error looking up service account default/gsa-metaflow-default: serviceaccount "gsa-metaflow-default" not found

although, this may be very old; that pod is not found when I search for it. The

kubectl logs

output:

Setting up task environment.
Downloading code package...
Code package downloaded.
Task is starting.
Compiling model
R[write to console]: Compiling Stan program...

bash: line 1:    59 Killed                  ( python -u sfflow.py --quiet --metadata service --environment pypi --datastore gs --event-logger nullSidecarLogger --monitor nullSidecarMonitor --datastore-root <gs://storage-genflow-dev-metaflow-default/tf-full-stack-sysroot> --with 'conda:packages={},python=3.9.18,disabled=True' --package-suffixes .py,.R,.RDS --pylint step sample_posterior --run-id 438 --task-id 2247 --input-paths ${METAFLOW_INPUT_PATHS_0} --retry-count 0 --max-user-code-retries 0 --namespace user:jburos ) >> >(python -m metaflow.mflog.tee task $MFLOG_STDOUT) 2>> >(python -m metaflow.mflog.tee task $MFLOG_STDERR 1>&2)

hmm yeah I wonder if something within that R/stan code path sends sigkill for whatever reason

I'm using osx, and it does reproduce locally (errors in metaflow, runs in ipython)

ok I was going to suggest

strace -f

to try to find out what sends SIGKILL, but strace is not available on linux, and kind of pain to set it up in k8s 🤔

this gives me something to dig into further!

hmm that

wsl

stuff is weird, i think its actually looking for windows wsl thingy

Yeah it's pretty odd that it's looking for

wsl

. I ran it like this:

strace -f poetry run python ...

.

If you can somehow create a virtual env of some sort, with a python binary, I would try

strace -f /path/to/python/binary flow.py ...

just in case, if you do

strace -f poetry run python ..

I worry if strace will follow the correct process tree, I think I ran into some issues with this in the past

To the

virtualenv

question, I just re-used the one poetry creates by calling that python binary. I don't know if this will re-create the issues you remember, but this should be the same as creating a new virtualenv. I also modified the installation to use the cmdstanr ref

v0.6.1

. Under these conditions, I don't think the trace is very different:

[pid 80590] close(193)                  = -1 EBADF (Bad file descriptor)
[pid 80590] close(194)                  = -1 EBADF (Bad file descriptor)
[pid 80590] close(195)                  = -1 EBADF (Bad file descriptor)
[pid 80590] close(196)                  = -1 EBADF (Bad file descriptor)
[pid 80590] close(197)                  = -1 EBADF (Bad file descriptor)
[pid 80590] close(198)                  = -1 EBADF (Bad file descriptor)
[pid 80590] close(199)                  = -1 EBADF (Bad file descriptor)
[pid 80590] close(200)                  = -1 EBADF (Bad file descriptor)
[pid 80590] close(201)                  = -1 EBADF (Bad file descriptor)
[pid 80590] chdir("/home/user/test-metaflow") = 0
[pid 80590] execve("/home/user/miniforge3/envs/metaflow_676a7146461c6557920547668cc3268d7ebd4f4e_ef98d3ee74b3b0660c6e9f3d80b1b4a016c1290d/bin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/home/user/miniforge3/bin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/home/user/.local/bin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/opt/code-oss/bin/remote-cli/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/home/user/.local/bin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/home/user/.local/bin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/usr/local/sbin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/usr/local/bin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/usr/sbin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/usr/bin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/sbin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/bin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/usr/local/go/bin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/usr/local/go/bin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/usr/local/go/bin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] execve("/usr/local/go/bin/wsl", ["wsl", "uname"], 0x5c9e16169010 /* 76 vars */) = -1 ENOENT (No such file or directory)
[pid 80590] write(12, "\376\377\377\377", 4) = 4
[pid 79632] <... read resumed>"\376\377\377\377", 4) = 4
[pid 80590] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1],  <unfinished ...>
[pid 79632] wait4(80590,  <unfinished ...>
[pid 80590] <... rt_sigprocmask resumed>[], 8) = 0
[pid 80590] getpid()                    = 80590
[pid 80590] gettid()                    = 80590
[pid 80590] tgkill(80590, 80590, SIGKILL) = ?
[pid 80590] +++ killed by SIGKILL +++
[pid 79632] <... wait4 resumed>[{WIFSIGNALED(s) && WTERMSIG(s) == SIGKILL}], 0, NULL) = 80590
[pid 79632] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_KILLED, si_pid=80590, si_uid=1000, si_status=SIGKILL, si_utime=0, si_stime=1} ---
[pid 79632] wait4(80590, 0x7ffd878ab9b4, WNOHANG, NULL) = -1 ECHILD (No child processes)
[pid 79632] rt_sigreturn({mask=[]})     = 80590
[pid 79632] close(11)                   = 0
[pid 79632] rt_sigprocmask(SIG_BLOCK, [CHLD], NULL, 8) = 0
[pid 79632] wait4(0, 0x7ffd878754e4, WNOHANG, NULL) = 0
[pid 79632] kill(0, SIGKILLKilled

I'm running this for a normal R process installing cmdstan for comparison. I don't see any mention of

wsl

in the strace from the R process.

hmm looking closer, i was wrong, that code still exists in 0.6.1. So this doesn't rule it out being the culprit

Hi again, I managed to run this with the

-fy

flags although the

-Y

doesn't work for the flavor of strace I have installed. More output is here: https://gist.github.com/jburos/8df4f05e5502a37178e5a30b22f7c068 though, i'm not sure it includes enough of the output. I was noticing the child process with PID 51913 was killed, here: https://gist.github.com/jburos/8df4f05e5502a37178e5a30b22f7c068#file-gistfile1-txt-L22 I'm not familiar with reading strace logs, .. really appreciate your help to date on this I realize it's extra! For next steps, I'm thinking to set up a simpler example of an R script that just spawns sub-processes to try to find the culprit.

I think that kill is kind of expected, the way R processx library its written, it creates a thread that tries to launch wsl process and then it gets killed when it fails. If I just strace a little R program that tries to do processx:new, I see the same

tgkill