Weird strace of #! python script

[Eugene Syromyatnikov]

On Tue, Mar 15, 2022 at 1:00 AM Dan Stromberg <drsalists at gmail.com> wrote:
> On Mon, Mar 14, 2022 at 3:23 PM Eugene Syromyatnikov <evgsyr at gmail.com> wrote:
>> On Mon, Mar 14, 2022 at 10:37 PM Dan Stromberg <drsalists at gmail.com> wrote:
>> > So anyway, I'm strace'ing a #!/usr/bin/python2 script.
>> >
>> > I expected to see an exec of /usr/bin/python2, but I don't.  I just see an
>> > exec of /tmp/t.
>>
>> Why, exactly, did you expect that? strace doesn't parse binary
>> supplied as a command (or runs a shell to do so), it just executes it
>> (as stated in the NOTES section in the man page[0]). The parsing of
>> the interpreter is performed in-kernel by the binfmt_script loader[1]
>> (along with all its limitations like interpreter command line size and
>> single argument only).
>
>
> I thought I had seen a second exec for a #! script, but perhaps I was misremembering.

If there is a single syscall performed in the user space, then it will
be handled once, as a single syscall. The only case of having multiple
syscalls performed per one user space syscall I can think of is
restart_syscall(2), and it is different. I don't think it is possible
to get multiple execve() records in trace per one syscall with seccomp
(well, it can overwrite the arguments, and theortically get the
suggested "/usr/bin/python2" output, for example, but it still will be
a single syscall, and such syscall overwriting would require prepared
argv string, which is likely require ptrace attachment for tracees
thatdo not cooperate, that is not availailable for tracees already
ptraced by strace).

>> Is that script run in a shell? That would explain it.
>
> The larger script is clone'd and execve'd by a C++ program.

Then, I suspect, the trace would be the same. Even with shell, the
script binary is execve'd and not the interpreter:

% cat t.py
#! /usr/bin/python3

print("OH HAI")
% strace -f -e/^execv.\* /bin/sh -c './t.py'
execve("/bin/sh", ["/bin/sh", "-c", "./t.py"], 0x7ffc7946f510 /* 43 vars */) = 0
strace: Process 22983 attached
[pid 22983] execve("./t.py", ["./t.py"], 0x5617d1106b48 /* 43 vars */) = 0
OH HAI
[pid 22983] +++ exited with 0 +++
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=22983,
si_uid=1000, si_status=0, si_utime=1, si_stime=0} ---
+++ exited with 0 +++
% strace -f -e/^execv.\* /bin/bash -c './t.py'
execve("/bin/bash", ["/bin/bash", "-c", "./t.py"], 0x7ffc02332b60 /*
43 vars */) = 0
execve("./t.py", ["./t.py"], 0x55a485e99870 /* 43 vars */) = 0
OH HAI
+++ exited with 0 +++
% strace -f -e/^execv.\* /usr/bin/zsh -c './t.py'
execve("/usr/bin/zsh", ["/usr/bin/zsh", "-c", "./t.py"],
0x7ffef9ec5120 /* 43 vars */) = 0
execve("./t.py", ["./t.py"], 0x7ffdab11db08 /* 43 vars */) = 0
OH HAI
+++ exited with 0 +++

> It's possible I collected the strace outputs too soon, but I see another Python program logging messages that don't show up in the strace.

What kinds of messages? Some may be library calls that do not result
in syscalls; some may be from child processes that are not traced
without -f.

-- 
Eugene Syromyatnikov
mailto:evgsyr at gmail.com
xmpp:esyr at jabber.{ru|org}