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
>
