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: Wed, 18 Oct 2017 08:21:11 +0200
Subject: Re: new logging
Message-Id: <F13BD163-C81C-4640-9A86-4F17342E24AA@gmail.com>
References: <CANRT7T1Se6jxax9QcX25ic+Pu9rnVD+-pVaQmTNW2AuVhK4dAw@mail.gmail.com> <CAC15uRvsYs4kjmg93qbwaPNzuu2XVhdMF+NWULD7BsV-TT_QcA@mail.gmail.com> <CANRT7T3qVibXRj1aOsr_nO5gax20whHjQGcC+=CqGZKtgQb76w@mail.gmail.com> <CALZjm2JBAjoAEN0GHMhQnu3OJih2_ojjFkCwdL51yDr5=2O2WQ@mail.gmail.com> <CAC15uRs_S9Thjv0YZzN4SFu6UFYO+BUVV_+pqaPichkOP_Vbcg@mail.gmail.com> <CANRT7T2a0g5gxCP8OT4P6Es2wFrQ2zC_yx4vhdN4PZe66beS_w@mail.gmail.com>
In-Reply-To: <CANRT7T2a0g5gxCP8OT4P6Es2wFrQ2zC_yx4vhdN4PZe66beS_w@mail.gmail.com>
To: dev@airflow.incubator.apache.org
archived-at: Wed, 18 Oct 2017 06:21:30 -0000

You should always init the logger. It is bad practice not to do it.=20

Log =3D logging.getLogger(__name__)=20

Is the canonical way. In Airflow we provide some convenience functions for o=
perators etc. The loggingmixin can help out.

Bolke

Verstuurd vanaf mijn iPad

> Op 17 okt. 2017 om 20:21 heeft Boris Tyukin <boris@boristyukin.com> het vo=
lgende geschreven:
>=20
> thank you both! so my understanding instead one liner like
> logging.info("something")
>=20
> I need to init logger first in a python operator and only after that I can=

> invoke logger.info like below. This is a bit unexpected and a bit more wor=
k
> but it does work now - thanks. Maybe I was not doing it right in the first=

> place but hey it did work in 1.8 :)
>=20
> logger =3D logging.getLogger('airflow.python_test_logging')
> logger.info('hi from loggin info')
>=20
> On Tue, Oct 17, 2017 at 6:35 AM, Driesprong, Fokko <fokko@driesprong.frl>
> wrote:
>=20
>> Hi Boris,
>>=20
>> This is interesting.
>>=20
>> When I run the example you provide with the latest Airflow release, I get=
:
>> root@9e3cf03c0544:~# airflow test python_test_logging print_the_context
>> 2017-01-01
>> [2017-10-17 10:27:38,321] {__init__.py:45} INFO - Using executor
>> SequentialExecutor
>> [2017-10-17 10:27:38,359] {models.py:186} INFO - Filling up the DagBag fr=
om
>> /root/airflow/dags
>> [2017-10-17 10:27:38,406] {dag.py:30} WARNING - test warn
>> [2017-10-17 10:27:38,406] {dag.py:31} INFO - test info
>> [2017-10-17 10:27:38,429] {models.py:1165} INFO - Dependencies all met fo=
r
>> <TaskInstance: python_test_logging.print_the_context 2017-01-01 00:00:00
>> [None]>
>> [2017-10-17 10:27:38,432] {models.py:1165} INFO - Dependencies all met fo=
r
>> <TaskInstance: python_test_logging.print_the_context 2017-01-01 00:00:00
>> [None]>
>> [2017-10-17 10:27:38,432] {models.py:1375} INFO -
>> ------------------------------------------------------------
>> --------------------
>> Starting attempt 1 of 1
>> ------------------------------------------------------------
>> --------------------
>>=20
>> [2017-10-17 10:27:38,433] {models.py:1396} INFO - Executing
>> <Task(PythonOperator): print_the_context> on 2017-01-01 00:00:00
>> {'END_DATE': '2017-01-01',
>> 'conf': <module 'airflow.configuration' from
>> '/usr/local/lib/python3.6/site-packages/airflow/configuration.py'>,
>> 'dag': <DAG: python_test_logging>,
>> 'dag_run': None,
>> 'ds_nodash': '20170101',
>> 'end_date': '2017-01-01',
>> 'execution_date': datetime.datetime(2017, 1, 1, 0, 0),
>> 'latest_date': '2017-01-01',
>> 'macros': <module 'airflow.macros' from
>> '/usr/local/lib/python3.6/site-packages/airflow/macros/__init__.py'>,
>> 'next_execution_date': None,
>> 'params': {},
>> 'prev_execution_date': None,
>> 'run_id': None,
>> 'tables': None,
>> 'task': <Task(PythonOperator): print_the_context>,
>> 'task_instance': <TaskInstance: python_test_logging.print_the_context
>> 2017-01-01 00:00:00 [None]>,
>> 'task_instance_key_str':
>> 'python_test_logging__print_the_context__20170101',
>> 'templates_dict': None,
>> 'test_mode': True,
>> 'ti': <TaskInstance: python_test_logging.print_the_context 2017-01-01
>> 00:00:00 [None]>,
>> 'tomorrow_ds': '2017-01-02',
>> 'tomorrow_ds_nodash': '20170102',
>> 'ts': '2017-01-01T00:00:00',
>> 'ts_nodash': '20170101T000000',
>> 'var': {'json': None, 'value': None},
>> 'yesterday_ds': '2016-12-31',
>> 'yesterday_ds_nodash': '20161231'}
>> hi from print
>> [2017-10-17 10:27:38,441] {python_operator.py:90} INFO - Done. Returned
>> value was: None
>>=20
>> When I change it to `warn`, I do get:
>> WARNING:root:hi from loggin info
>>=20
>> =E2=80=8B=E2=80=8BBy giving an explicit logger, as Daniel suggested, that=
 starts with
>> airflow%:
>> def print_context(ds, **kwargs):
>>    pprint(kwargs)
>>    print('hi from print')
>>    logger =3D logging.getLogger('airflow.python_test_logging')
>>    logger.info('hi from loggin info')
>>=20
>> =E2=80=8BThen it is picked up by the Airflow logging context=E2=80=8B:
>> [2017-10-17 10:31:05,639] {dag.py:23} INFO - hi from loggin info
>>=20
>> =E2=80=8BThis is how the current logging is set:
>> https://github.com/apache/incubator-airflow/blob/master/
>> airflow/config_templates/airflow_local_settings.py
>>=20
>> Currently I'm investigating why it used to work in Airflow 1.8. This is n=
ot
>> yet clear to me.
>>=20
>> Cheers, Fokko=E2=80=8B
>>=20
>>=20
>> 2017-10-17 7:58 GMT+02:00 Daniel Lamblin [Data Science & Platform Center]=
 <
>> lamblin@coupang.com>:
>>=20
>>> Boris, I don't see where you configured the default logger
>>> <https://docs.python.org/2/howto/logging.html#configuring-logging>. I
>>> think
>>> you'd have to at least throw in:
>>>    logger =3D logging.getLogger('python_test_logging')
>>> and then use the logger.info(=E2=80=A6) instead of logging.info(=E2=80=A6=
)
>>>=20
>>> On Tue, Oct 17, 2017 at 3:00 AM, Boris Tyukin <boris@boristyukin.com>
>>> wrote:
>>>=20
>>>> sorry i was not clear.
>>>>=20
>>>> In DAG definition file, I would normally import logging and when use
>> with
>>>> python operator like below (see print_context).
>>>>=20
>>>> In 1.8.2 i would see in Airflow log file (for that task) both 'hi from
>>>> print' and 'hi from logging'.
>>>>=20
>>>> now I can only see 'hi from print'.
>>>>=20
>>>> I installed from master (pip install), and used newer airflow.cfg file.=

>>>> Only updated it to use local executor and mysql db. Did not change any
>>>> other settings.
>>>>=20
>>>> So my question if it is supposed to work like that and how do I log now=

>>>> from python operators in a dag.
>>>>=20
>>>>=20
>>>> =EF=BB=BFfrom __future__ import print_function
>>>> from builtins import range
>>>> import airflow
>>>> from airflow.operators.python_operator import PythonOperator
>>>> from airflow.models import DAG
>>>> import logging
>>>> import time
>>>> from pprint import pprint
>>>>=20
>>>> args =3D {
>>>>    'owner': 'airflow',
>>>>    'start_date': airflow.utils.dates.days_ago(2)
>>>> }
>>>>=20
>>>> dag =3D DAG(
>>>>    dag_id=3D'python_test_logging', default_args=3Dargs,
>>>>    schedule_interval=3DNone)
>>>>=20
>>>> def print_context(ds, **kwargs):
>>>>    pprint(kwargs)
>>>>    print('hi from print')
>>>>    logging.info('hi from loggin info')
>>>>=20
>>>> run_this =3D PythonOperator(
>>>>    task_id=3D'print_the_context',
>>>>    provide_context=3DTrue,
>>>>    python_callable=3Dprint_context,
>>>>    dag=3Ddag)
>>>>=20
>>>>=20
>>>> On Mon, Oct 16, 2017 at 1:09 PM, Driesprong, Fokko
>> <fokko@driesprong.frl
>>>>=20
>>>> wrote:
>>>>=20
>>>>> Hi Boris,
>>>>>=20
>>>>> Can you please elaborate? Where did the output used to end up? Did
>> you
>>>>> provide any custom logging config, or are you using the default
>> config?
>>>>> Maybe drop some example code.
>>>>>=20
>>>>> Cheers, Fokko
>>>>>=20
>>>>> 2017-10-16 19:02 GMT+02:00 Boris <boriskey@gmail.com>:
>>>>>=20
>>>>>> Hi guys,
>>>>>>=20
>>>>>> I used to do logging.info("somthing") from airflow python
>> operators
>>>> so i
>>>>>> can see output in airflow logs. Worked fine in 1.8.2.
>>>>>>=20
>>>>>> Looks like this is no longer the case with master branch.I did look
>>> at
>>>>>> updating.md but still not clear how to log custom messages from
>>> python
>>>>>> operators.
>>>>>>=20
>>>>>> please advise.
>>>>>>=20
>>>>>=20
>>>>=20
>>>=20
>>>=20
>>>=20
>>> --
>>> -Daniel Lamblin
>>>=20
>>=20