self.log.info(“xxx”) Works in every other operator, so please provide code in order to help you.
Bolke. > On 17 Nov 2017, at 19:25, Kevin Lam <[email protected]> wrote: > > Sorry for spam! To clarify again, the expected behaviour is that the > logging.info calls in the custom operator would be forwarded to the > base_task_runner and then be available for viewing in the task logs in the > Airflow Web UI. > > On Fri, Nov 17, 2017 at 1:20 PM, Kevin Lam <[email protected]> wrote: > >> Note that in 1.8 the behaviour is as expected. Thanks again! >> >> On Fri, Nov 17, 2017 at 1:17 PM, [email protected] < >> [email protected]> wrote: >> >>> Hi, >>> >>> I'm encountering a seemingly related issue in 1.9. >>> >>> I have a custom Airflow Operator that I want to log from and none of the >>> outputs seems to get forwarded to the Task Logs in the Airflow Web UI >>> except for when I use STDOUT via print(). >>> >>> My custom operator inherits from the BashOperator and I've tried logging >>> the following other ways: >>> >>> - using self.log passed from BaseOperator >>> - initializing the logger with log = logging.getLogger(__name__) >>> - making sure to set the logging level in a airflow.cfg >>> >>> Do you know if there is something we should be otherwise doing? >>> >>> Thanks in advance for your help! >>> >>> On 2017-10-18 07:00, Boris <[email protected]> wrote: >>>> Got it, thanks Bolke >>>> >>>> On Oct 18, 2017 2:21 AM, "Bolke de Bruin" <[email protected]> wrote: >>>> >>>>> 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 <[email protected]> >>> 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 >>> <[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/configuratio >>> n.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 >>>>>>>> >>>>>>> >>>>> >>>> >>> >> >>
