Mailing-List: contact dev-help@airflow.incubator.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@airflow.incubator.apache.org
From: Bolke de Bruin <bdbruin@gmail.com>
Content-Type: text/plain;
	charset=utf-8
Content-Transfer-Encoding: quoted-printable
Mime-Version: 1.0 (1.0)
Date: Thu, 30 Nov 2017 18:24:42 +0100
Subject: Re: [VOTE] Airflow 1.9.0rc4
Message-Id: <38E294B1-7641-459E-B642-A3E19B6341C6@gmail.com>
References: <CABYbY7eeCbrKDTQvsS9LJ_XKFkJx19DrOp0DXdNXttpmkJ7xDw@mail.gmail.com> <70326A1F-46C0-450A-AC34-194722EA2C56@gmail.com> <CAC15uRt9mNoifbtSTh95BycHUWQFuJ_HPe3WTom39CESF+yiCg@mail.gmail.com> <CABYbY7cKCCgKdJKS1CAU-e1y=F2niWFCMDpJBqyKN8c6Wi-yOA@mail.gmail.com> <754FC338-773C-46FC-BC33-B35630FC39EC@firemirror.com> <86ACB8DC-F946-4572-999A-30179567F5A7@firemirror.com> <2787914E-9ADF-49C7-A8C3-4D23EAB83E47@firemirror.com> <51B99D9F-3DBE-452B-A04A-1852A90DD8D4@gmail.com> <69ED3101-0DEC-41C3-B6CA-DD5E9BE2715B@firemirror.com> <70828941-8CEA-4559-B415-743368A06448@firemirror.com> <CABYbY7czp-fXKVHG-VHP2kdGQZB5UE7Dpii8MsYuhuT6HG9xSQ@mail.gmail.com> <DC5A7DA5-33E4-4075-B121-9BEE52DEF3D9@firemirror.com> <CABYbY7fbX0yW9A30btLcoVL2O1TvgVA4SiPGDZ6iwy_AL49j2Q@mail.gmail.com>
In-Reply-To: <CABYbY7fbX0yW9A30btLcoVL2O1TvgVA4SiPGDZ6iwy_AL49j2Q@mail.gmail.com>
To: dev@airflow.incubator.apache.org
archived-at: Thu, 30 Nov 2017 17:24:51 -0000

We saw this issue around RC2, so I=E2=80=99m surprised that it turns up agai=
n. We discussed it at lengths with Fokko and Joy. It might be that we someho=
w missed a commit, but I need to double check a from stock install. We are r=
unning 1.9 in production and we don=E2=80=99t have any logging issues.

B.

Verstuurd vanaf mijn iPad

> Op 30 nov. 2017 om 18:17 heeft Chris Riccomini <criccomini@apache.org> het=
 volgende geschreven:
>=20
> @bolke/@fokko, thoughts?
>=20
> As an aside, we had an issue seeing task logs, but were able to fix it by
> modifying our logging config (and perhaps patching some stuff that we
> merged into 1.9.0, don't recall). William Pursell/Joy Gao might be able to=

> comment more.
>=20
> On Thu, Nov 30, 2017 at 9:08 AM, Ash Berlin-Taylor <
> ash_airflowlist@firemirror.com> wrote:
>=20
>> If anyone else is seeing this (and I think I'm on stock configuration now=
)
>> yes I do, as I'm not seeing _any_ logs form task operators appearing.
>>=20
>> There's another problem after applying a local fix for
>> `handler.set_context()`, to do with try_numbers:
>>=20
>> The `airflow run tests test-logging 2017-11-26T00:00:00 --local -sd
>> /usr/local/airflow/dags/example/.py` command sends logs to .../14.log
>>=20
>> The `airflow run tests test-logging 2017-11-26T00:00:00 --job_id 33 --raw=

>> -sd /usr/local/airflow/dags/example/.py` command (that the previous
>> command invokes) sends logs to .../15.log
>>=20
>> However the UI doesn't know about try 15 (yes try 15. I've been running
>> this a bit) so any future runs will write to this file.
>>=20
>> At this point I might be a bit deep and might need to look with fresh eye=
s
>> and a clean slate tomorrow. Someone confirming if they do or don't see lo=
gs
>> from inside an operator would help me.
>>=20
>> -ash
>>=20
>>=20
>>> On 30 Nov 2017, at 17:03, Chris Riccomini <criccomini@apache.org> wrote:=

>>>=20
>>> @Ash, do you think this issue is blocking for 1.9.0?
>>>=20
>>> On Thu, Nov 30, 2017 at 8:22 AM, Ash Berlin-Taylor <
>>> ash_airflowlist@firemirror.com> wrote:
>>>=20
>>>> Ah, I think I've got it.
>>>>=20
>>>> The problem is that airflow.task.raw doesn't have an explicit config
>>>> anymore(?), so when we do:
>>>>=20
>>>> log =3D logging.getLogger('airflow.task.raw')
>>>>=20
>>>> and look at its handlers, it doesn't have any. But log.parent.handlers
>>>> _does_ have them.
>>>>=20
>>>> A few options to fix this:
>>>>=20
>>>> - I can add an explicit handler for .task.raw in my logging config.
>>>> - We can always call set_context on airflow.task instead of
>>>> airflow.task.raw
>>>> - We walk up the .parent links if .propagate is True (possibly stopping=

>>>> once we find any handlers)
>>>>=20
>>>> -ash
>>>>=20
>>>>=20
>>>>> On 30 Nov 2017, at 16:02, Ash Berlin-Taylor
>> <ash_airflowlist@firemirror.
>>>> com> wrote:
>>>>>=20
>>>>> I'm fairly sure I'm back to stock config now. Here is the DAG I am
>>>> testing with:
>>>>>=20
>>>>> from datetime import datetime
>>>>> from airflow import DAG
>>>>> from airflow.operators.python_operator import PythonOperator
>>>>>=20
>>>>> dag_args =3D {
>>>>>  "start_date": datetime(2017, 11, 20),
>>>>> }
>>>>> dag =3D DAG("tests", default_args=3Ddag_args)
>>>>>=20
>>>>>=20
>>>>> def print_stuff(ti, **kwargs):
>>>>>  print("Hi from", __file__)
>>>>>  ti.log.error("Hello")
>>>>>=20
>>>>> with dag:
>>>>>  PythonOperator(
>>>>>      task_id=3D"test-logging",
>>>>>      dag=3Ddag,
>>>>>      python_callable=3Dprint_stuff,
>>>>>      provide_context=3DTrue,
>>>>>  )
>>>>>=20
>>>>>=20
>>>>> And I don't see either of the "Hi from" or "Hello" lines in the
>>>> resulting log file. I have edited airflow/logging_config.py to print th=
e
>>>> config before it uses it, and this is the config I'm getting:
>>>>>=20
>>>>> {'disable_existing_loggers': False,
>>>>> 'formatters': {'airflow.processor': {'format': '[%(asctime)s] '
>>>>>=20
>>>> '{%(filename)s:%(lineno)d} '
>>>>>                                              '%(levelname)s -
>>>> %(message)s'},
>>>>>              'airflow.task': {'format': '[%(asctime)s] '
>>>>>                                         '{%(filename)s:%(lineno)d} '
>>>>>                                         '%(levelname)s -
>>>> %(message)s'}},
>>>>> 'handlers': {'console': {'class': 'logging.StreamHandler',
>>>>>                        'formatter': 'airflow.task',
>>>>>                        'stream': 'ext://sys.stdout'},
>>>>>            'file.processor': {'base_log_folder':
>>>> '/usr/local/airflow/logs/scheduler',
>>>>>                               'class': 'airflow.utils.log.file_
>>>> processor_handler.FileProcessorHandler',
>>>>>                               'filename_template': '{{ filename
>>>> }}.log',
>>>>>                               'formatter': 'airflow.processor'},
>>>>>            'file.task': {'base_log_folder':
>> '/usr/local/airflow/logs/',
>>>>>                          'class': 'airflow.utils.log.file_task_
>>>> handler.FileTaskHandler',
>>>>>                          'filename_template': '{{ ti.dag_id }}/{{ '
>>>>>                                               'ti.task_id }}/{{ ts
>>>> }}/{{ '
>>>>>                                               'try_number }}.log',
>>>>>                          'formatter': 'airflow.task'}},
>>>>> 'loggers': {'': {'handlers': ['console'], 'level': 'INFO'},
>>>>>           'airflow': {'handlers': ['console'],
>>>>>                       'level': 'INFO',
>>>>>                       'propagate': False},
>>>>>           'airflow.processor': {'handlers': ['file.processor'],
>>>>>                                 'level': 'INFO',
>>>>>                                 'propagate': True},
>>>>>           'airflow.task': {'handlers': ['file.task'],
>>>>>                            'level': 'INFO',
>>>>>                            'propagate': False},
>>>>>           'airflow.task_runner': {'handlers': ['file.task'],
>>>>>                                   'level': 'INFO',
>>>>>                                   'propagate': True}},
>>>>>=20
>>>>>=20
>>>>> If I edit run() in in bin/cli.py to print the log.handlers under this
>>>> circumstance I get an empty list [].
>>>>>=20
>>>>> I guess since we don't specify 'airflow.task.raw' in the loggers that
>> it
>>>> should go up to the next level in 'airflow.task'? Except it doesn't
>> seem to
>>>> be for me. I'm digging further.
>>>>>=20
>>>>> -ash
>>>>>=20
>>>>>=20
>>>>>=20
>>>>>> On 30 Nov 2017, at 15:38, Bolke de Bruin <bdbruin@gmail.com> wrote:
>>>>>>=20
>>>>>> airflow.task.raw points to airflow.task by default, which does have a=

>>>> handler and that is the one that is travelled. And yes we know the code=

>> is
>>>> incorrect in this area, but the default does work correctly.
>>>>>>=20
>>>>>> Bolke.
>>>>>>=20
>>>>>>=20
>>>>>>> On 30 Nov 2017, at 16:27, Ash Berlin-Taylor <
>>>> ash_airflowlist@firemirror.com> wrote:
>>>>>>>=20
>>>>>>> Okay I think the problem (if not the cause) is around here:
>>>> https://github.com/apache/incubator-airflow/blob/master/
>>>> airflow/bin/cli.py#L366-L376
>>>>>>>=20
>>>>>>>=20
>>>>>>>=20
>>>>>>> log =3D logging.getLogger('airflow.task')
>>>>>>> if args.raw:
>>>>>>> log =3D logging.getLogger('airflow.task.raw')
>>>>>>>=20
>>>>>>> for handler in log.handlers:
>>>>>>> try:
>>>>>>>    handler.set_context(ti)
>>>>>>> except AttributeError:
>>>>>>>    # Not all handlers need to have context passed in so we ignore
>>>>>>>    # the error when handlers do not have set_context defined.
>>>>>>> pass
>>>>>>>=20
>>>>>>> The problem seems to be that airflow.task.raw is no longer configure=
d
>>>> explicitly, so it's log.handlers is an empty list.
>>>>>>>=20
>>>>>>> This in turn means that any log calls end up not writing anything as=

>>>> our FileTaskHandler's self.handler property is None, meaning it doesn't=

>>>> emit anything.
>>>>>>>=20
>>>>>>> Does this ring any bells to anyone?
>>>>>>>=20
>>>>>>>=20
>>>>>>>> On 30 Nov 2017, at 15:18, Ash Berlin-Taylor <
>>>> ash_airflowlist@firemirror.com> wrote:
>>>>>>>>=20
>>>>>>>> Hmmm is anyone else seeing logs from inside operators? Right now
>>>> we're not getting any logs out of operators. I'm in the process of
>>>> debugging to work out if it's our logging config or something in
>> Airflow,
>>>> but right now I don't seem to get any output from the operator itself,
>>>> neither print(), or `ti.log.info()`
>>>>>>>>=20
>>>>>>>> Anyone else noticed similar, or is it something specific to our
>>>> environment?
>>>>>>>>=20
>>>>>>>> -ash
>>>>>>>>=20
>>>>>>>>> On 30 Nov 2017, at 09:52, Ash Berlin-Taylor <
>>>> ash_airflowlist@firemirror.com> wrote:
>>>>>>>>>=20
>>>>>>>>> We're running more tests (day of meetings meant we couldn't do as
>>>> many as I'd have liked yesterday) but looking good so far.
>>>>>>>>>=20
>>>>>>>>> +0.5 (non binding)
>>>>>>>>>=20
>>>>>>>>> -ash
>>>>>>>>>=20
>>>>>>>>>> On 29 Nov 2017, at 18:31, Chris Riccomini <criccomini@apache.org>=

>>>> wrote:
>>>>>>>>>>=20
>>>>>>>>>> Anyone else? Last day before I close the vote off.
>>>>>>>>>>=20
>>>>>>>>>> On Mon, Nov 27, 2017 at 12:32 PM, Driesprong, Fokko
>>>> <fokko@driesprong.frl>
>>>>>>>>>> wrote:
>>>>>>>>>>=20
>>>>>>>>>>> +1
>>>>>>>>>>>=20
>>>>>>>>>>> Op ma 27 nov. 2017 om 21:24 schreef Bolke de Bruin <
>>>> bdbruin@gmail.com>
>>>>>>>>>>>=20
>>>>>>>>>>>> +1, binding
>>>>>>>>>>>>=20
>>>>>>>>>>>> Let=E2=80=99s get it out!
>>>>>>>>>>>>=20
>>>>>>>>>>>> Sent from my iPhone
>>>>>>>>>>>>=20
>>>>>>>>>>>>> On 27 Nov 2017, at 20:32, Chris Riccomini <
>> criccomini@apache.org
>>>>>=20
>>>>>>>>>>> wrote:
>>>>>>>>>>>>>=20
>>>>>>>>>>>>> Hey all,
>>>>>>>>>>>>>=20
>>>>>>>>>>>>> I have cut Airflow 1.9.0 RC4. This email is calling a vote on
>> the
>>>>>>>>>>>> release,
>>>>>>>>>>>>> which will last for 72 hours. Consider this my (binding) +1.
>>>>>>>>>>>>>=20
>>>>>>>>>>>>> Airflow 1.9.0 RC4 is available at:
>>>>>>>>>>>>>=20
>>>>>>>>>>>>> https://dist.apache.org/repos/dist/dev/incubator/airflow/1.
>>>> 9.0rc4/
>>>>>>>>>>>>>=20
>>>>>>>>>>>>> apache-airflow-1.9.0rc4+incubating-source.tar.gz is a source
>>>> release
>>>>>>>>>>> that
>>>>>>>>>>>>> comes with INSTALL instructions.
>>>>>>>>>>>>> apache-airflow-1.9.0rc4+incubating-bin.tar.gz is the binary
>>>> Python
>>>>>>>>>>>> "sdist"
>>>>>>>>>>>>> release.
>>>>>>>>>>>>>=20
>>>>>>>>>>>>> Public keys are available at:
>>>>>>>>>>>>>=20
>>>>>>>>>>>>> https://dist.apache.org/repos/dist/release/incubator/airflow/
>>>>>>>>>>>>>=20
>>>>>>>>>>>>> The release contains the following JIRAs:
>>>>>>>>>>>>>=20
>>>>>>>>>>>>> *https://issues.apache.org/jira/browse/AIRFLOW-1839
>>>>>>>>>>>>> <https://issues.apache.org/jira/browse/AIRFLOW-1839>*
>>>>>>>>>>>>>=20
>>>>>>>>>>>>> Along with all JIRAs that were in 1.9.0RC3 (see previous VOTE
>>>> email for
>>>>>>>>>>>>> full list).
>>>>>>>>>>>>>=20
>>>>>>>>>>>>> Cheers,
>>>>>>>>>>>>> Chris
>>>>>>>>>>>>=20
>>>>>>>>>>>=20
>>>>>>>>>=20
>>>>>>>>=20
>>>>>>>=20
>>>>>>=20
>>>>>=20
>>>>=20
>>>>=20
>>=20
>>=20