Additional info about Segmentation Violation in LocalTaskJob

[Taragolis]

Attempt to add useful info when task ended with Negsignal.SIGSEGV (-11) or signal.SIGSEGV (11).
And highlight that something wrong environment:

• Mix C-libraries for different architecture arm64 and amd64/X86_64
• Mix C-libraries for different Operations Systems

[Taragolis]

Sample DAG

import os
import signal
import pendulum
from airflow.decorators import dag, task


@dag(
    schedule_interval=None,
    start_date=pendulum.datetime(2022, 1, 1, tz="UTC"),
    catchup=False,
    tags=["signal.SIGSEGV", "Return Code: 11", "Negsignal.SIGSEGV"]
)
def example_sigsegv():
    @task
    def sigsegv_signal():
        pid = os.getpid()
        os.kill(pid, signal.SIGSEGV)

    sigsegv_signal()


dag = example_sigsegv()

Task Output Log

[2022-10-30, 14:45:54 UTC] {taskinstance.py:1159} INFO - Dependencies all met for <TaskInstance: example_sigsegv.sigsegv_signal manual__2022-10-30T14:45:52.990793+00:00 [queued]>
[2022-10-30, 14:45:54 UTC] {taskinstance.py:1159} INFO - Dependencies all met for <TaskInstance: example_sigsegv.sigsegv_signal manual__2022-10-30T14:45:52.990793+00:00 [queued]>
[2022-10-30, 14:45:54 UTC] {taskinstance.py:1355} INFO - 
--------------------------------------------------------------------------------
[2022-10-30, 14:45:54 UTC] {taskinstance.py:1356} INFO - Starting attempt 1 of 1
[2022-10-30, 14:45:54 UTC] {taskinstance.py:1357} INFO - 
--------------------------------------------------------------------------------
[2022-10-30, 14:45:54 UTC] {taskinstance.py:1376} INFO - Executing <Task(_PythonDecoratedOperator): sigsegv_signal> on 2022-10-30 14:45:52.990793+00:00
[2022-10-30, 14:45:54 UTC] {standard_task_runner.py:55} INFO - Started process 1261 to run task
[2022-10-30, 14:45:54 UTC] {standard_task_runner.py:82} INFO - Running: ['airflow', 'tasks', 'run', 'example_sigsegv', 'sigsegv_signal', 'manual__2022-10-30T14:45:52.990793+00:00', '--job-id', '49', '--raw', '--subdir', 'DAGS_FOLDER/example_sigsegv.py', '--cfg-path', '/tmp/tmp3z3_7zqd']
[2022-10-30, 14:45:54 UTC] {standard_task_runner.py:83} INFO - Job 49: Subtask sigsegv_signal
[2022-10-30, 14:45:54 UTC] {task_command.py:376} INFO - Running <TaskInstance: example_sigsegv.sigsegv_signal manual__2022-10-30T14:45:52.990793+00:00 [running]> on host 2c85bba084bb
[2022-10-30, 14:45:54 UTC] {taskinstance.py:1585} INFO - Exporting the following env vars:
AIRFLOW_CTX_DAG_OWNER=airflow
AIRFLOW_CTX_DAG_ID=example_sigsegv
AIRFLOW_CTX_TASK_ID=sigsegv_signal
AIRFLOW_CTX_EXECUTION_DATE=2022-10-30T14:45:52.990793+00:00
AIRFLOW_CTX_TRY_NUMBER=1
AIRFLOW_CTX_DAG_RUN_ID=manual__2022-10-30T14:45:52.990793+00:00
[2022-10-30, 14:45:54 UTC] {local_task_job.py:176} CRITICAL - 
******************************************* Received SIGSEGV *******************************************
SIGSEGV (Segmentation Violation) signal indicates
an attempt by a program/library to write or read outside its allocated memory.

In Python environment usually this signal refers to libraries which use low level C API.
Make sure that you use use right libraries/Docker Images
for your architecture (Intel/ARM) and/or Operational System (Linux/macOS).
********************************************************************************************************
[2022-10-30, 14:45:54 UTC] {local_task_job.py:178} INFO - Task exited with return code Negsignal.SIGSEGV
[2022-10-30, 14:45:54 UTC] {local_task_job.py:287} INFO - 0 downstream tasks scheduled from follow-on schedule check

[potiuk]

LGTM!

[Taragolis]

I've plan add simple test today/tomorrow.

[potiuk]

@Taragolis - maybe we should also add a link to https://stackoverflow.com/questions/16731115/how-to-debug-a-python-segmentation-fault (or copying advice from it) and explanation that it's on user's discretion to debug for root cause.

Some of the previous discussions I had were that the users have an expectation that "airflow" will be better in diagnosing it, but there is really not much we can do in Airflow

Some users apparently had hard time to believe us when we tell them that we can't provide any more useful information on the root cause of the problem and they have to perform their own trial/error or deep C-level debugging. I think that messaging we do here might be great in setting expectations here and giving the users information (that otherwise can be googled) actually "written" by someone rather than "told" by people commenting on the issues is necessary. Especially in this issue #24463

Question: @binary-signal - would it be more believable if you saw those proposed messages written in the logs and the message that you need to do your own investigation to find a root cause? I believe this way we can at least avoid unnecesayr discussions when there are unrealistic expectations.

[Taragolis]

Yeah I agree more info we provide less questions would have end users.
I will add some additional steps/links which might help users to diagnosing their environment.

[binary-signal]

@potiuk more info is better than no info

[Taragolis]

Extend log info:

• Add how to use faulthandler and where user should check the logs. This might be an easier way for debug by end users. BTW, I can't personally catch any segmentation fault by pdb, might be I do something wrong.
• Add information about issue with proxies in macOs fork process

[Taragolis]

Hmmm... Task kill with SIGSEGV looks ugly in CI so I need to think how to disable faulthandler in single pytest test case or mock some part instead of actual kill it

[potiuk]

WDYM by ugly ?

[Taragolis]

[Taragolis]

I thought it might also confuse if some test fail in core section

[potiuk]

Not really - we have already some warnings in some tests - we really only look at the "test summary" when chasing the problems

[potiuk]

As long as we have green dots only, we are cool.

[Taragolis]

It is hard to me ignore any of SegFault errors 👀 even if it for testing purpose.

pytest collect warning and show them under the warning summary on the other hand everything catch by faulthandler (SIGSEGV, SIGFPE, SIGABRT, SIGBUS and SIGILL) would immediate write to stderr.

It is also possible to mock method airflow.jobs.local_task_job.get_task_runner.return_code and return any value that we required (11, -11 and might be 139) so in this case this message would gone.

Anyway I have no personal objections about this traceback

[uranusjr]

Why the abs? Positive and negative return codes are different values. If you want to remove trash bits over 256 you need a bit mask instead (but I don’t think that is necessary either)

[Taragolis]

Oh... I'm understand that I mix up kill signals (SIGSEGV = 11) and return_code which, I thought, depends on task_runner and for default StandardTaskRunner return code when task failed with Segmentation Fault in this case -11 and might be different for CgroupTaskRunner (I assume that 139 but need to check)

So might be better move this log message from airflow/jobs/local_task_job.pyy to a airflow/task/task_runner/standard_task_runner.py and airflow/task/task_runner/cgroup_task_runner.py? WDYT?

[uranusjr]

Exit codes except 0 and 1 are implementation-defined, and I’m not sure what cgexec returns for errors, so some trail-and-errors would probably be needed. If they do return different values for this situation, it’d make sense to put the log in runners.

[Taragolis]

Move log message from airflow/jobs/local_task_job.py to task runners

[Taragolis]

Third attempt for detect segfault and show info for end users by handling SIGSEGV signal.

@potiuk @uranusjr I'm not sure is this correct way to terminate task runner?

[uranusjr]

I’m not sure either (and not sure even if this would work), but segmentation faults are not the easiest to test, so we might as well just merge this and see how things go…

[Taragolis]

Locally it work fine but only with cases that I know (macOS specific stuff).

[potiuk]

Agree with @uranusjr . Let's merge and see. When you have SIGSEGV you are screwed anyway, we cannot get it any worse.