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 <[email protected]>
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] <
> [email protected]>:
>
> > 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 <[email protected]>
> > 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
> <[email protected]
> > >
> > > 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 <[email protected]>:
> > > >
> > > > > 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
> >
>
