airflow-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Bolke de Bruin <bdbr...@gmail.com>
Subject Re: new logging
Date Wed, 18 Oct 2017 06:21:11 GMT
You should always init the logger. It is bad practice not to do it. 

Log = logging.getLogger(__name__) 

Is the canonical way. In Airflow we provide some convenience functions for operators 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 volgende
geschreven:
> 
> thank you both! so my understanding instead one liner like
> logging.info("something")
> 
> 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 work
> 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 :)
> 
> logger = logging.getLogger('airflow.python_test_logging')
> logger.info('hi from loggin info')
> 
> On Tue, Oct 17, 2017 at 6:35 AM, Driesprong, Fokko <fokko@driesprong.frl>
> wrote:
> 
>> Hi Boris,
>> 
>> This is interesting.
>> 
>> 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 from
>> /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 for
>> <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 for
>> <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
>> ------------------------------------------------------------
>> --------------------
>> 
>> [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
>> 
>> When I change it to `warn`, I do get:
>> WARNING:root:hi from loggin info
>> 
>> ​​By giving an explicit logger, as Daniel suggested, that starts with
>> airflow%:
>> def print_context(ds, **kwargs):
>>    pprint(kwargs)
>>    print('hi from print')
>>    logger = logging.getLogger('airflow.python_test_logging')
>>    logger.info('hi from loggin info')
>> 
>> ​Then it is picked up by the Airflow logging context​:
>> [2017-10-17 10:31:05,639] {dag.py:23} INFO - hi from loggin info
>> 
>> ​This is how the current logging is set:
>> https://github.com/apache/incubator-airflow/blob/master/
>> airflow/config_templates/airflow_local_settings.py
>> 
>> Currently I'm investigating why it used to work in Airflow 1.8. This is not
>> yet clear to me.
>> 
>> Cheers, Fokko​
>> 
>> 
>> 2017-10-17 7:58 GMT+02:00 Daniel Lamblin [Data Science & Platform Center] <
>> lamblin@coupang.com>:
>> 
>>> 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 = logging.getLogger('python_test_logging')
>>> and then use the logger.info(…) instead of logging.info(…)
>>> 
>>> On Tue, Oct 17, 2017 at 3:00 AM, Boris Tyukin <boris@boristyukin.com>
>>> wrote:
>>> 
>>>> sorry i was not clear.
>>>> 
>>>> In DAG definition file, I would normally import logging and when use
>> with
>>>> python operator like below (see print_context).
>>>> 
>>>> In 1.8.2 i would see in Airflow log file (for that task) both 'hi from
>>>> print' and 'hi from logging'.
>>>> 
>>>> now I can only see 'hi from print'.
>>>> 
>>>> 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.
>>>> 
>>>> So my question if it is supposed to work like that and how do I log now
>>>> from python operators in a dag.
>>>> 
>>>> 
>>>> from __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
>>>> 
>>>> args = {
>>>>    'owner': 'airflow',
>>>>    'start_date': airflow.utils.dates.days_ago(2)
>>>> }
>>>> 
>>>> dag = DAG(
>>>>    dag_id='python_test_logging', default_args=args,
>>>>    schedule_interval=None)
>>>> 
>>>> def print_context(ds, **kwargs):
>>>>    pprint(kwargs)
>>>>    print('hi from print')
>>>>    logging.info('hi from loggin info')
>>>> 
>>>> run_this = PythonOperator(
>>>>    task_id='print_the_context',
>>>>    provide_context=True,
>>>>    python_callable=print_context,
>>>>    dag=dag)
>>>> 
>>>> 
>>>> On Mon, Oct 16, 2017 at 1:09 PM, Driesprong, Fokko
>> <fokko@driesprong.frl
>>>> 
>>>> wrote:
>>>> 
>>>>> Hi Boris,
>>>>> 
>>>>> 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.
>>>>> 
>>>>> Cheers, Fokko
>>>>> 
>>>>> 2017-10-16 19:02 GMT+02:00 Boris <boriskey@gmail.com>:
>>>>> 
>>>>>> Hi guys,
>>>>>> 
>>>>>> 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.
>>>>>> 
>>>>>> 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.
>>>>>> 
>>>>>> please advise.
>>>>>> 
>>>>> 
>>>> 
>>> 
>>> 
>>> 
>>> --
>>> -Daniel Lamblin
>>> 
>> 

Mime
View raw message