airflow-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ash Berlin-Taylor <ash_airflowl...@firemirror.com>
Subject Re: [VOTE] Airflow 1.9.0rc4
Date Thu, 30 Nov 2017 17:08:39 GMT
If anyone else is seeing this (and I think I'm on stock configuration now) yes I do, as I'm
not seeing _any_ logs form task operators appearing.

There's another problem after applying a local fix for `handler.set_context()`, to do with
try_numbers:

The `airflow run tests test-logging 2017-11-26T00:00:00 --local -sd /usr/local/airflow/dags/example/.py`
command sends logs to .../14.log

The `airflow run tests test-logging 2017-11-26T00:00:00 --job_id 33 --raw -sd /usr/local/airflow/dags/example/.py`
command (that the previous command invokes) sends logs to .../15.log

However the UI doesn't know about try 15 (yes try 15. I've been running this a bit) so any
future runs will write to this file.

At this point I might be a bit deep and might need to look with fresh eyes and a clean slate
tomorrow. Someone confirming if they do or don't see logs from inside an operator would help
me.

-ash


> On 30 Nov 2017, at 17:03, Chris Riccomini <criccomini@apache.org> wrote:
> 
> @Ash, do you think this issue is blocking for 1.9.0?
> 
> On Thu, Nov 30, 2017 at 8:22 AM, Ash Berlin-Taylor <
> ash_airflowlist@firemirror.com> wrote:
> 
>> Ah, I think I've got it.
>> 
>> The problem is that airflow.task.raw doesn't have an explicit config
>> anymore(?), so when we do:
>> 
>>  log = logging.getLogger('airflow.task.raw')
>> 
>> and look at its handlers, it doesn't have any. But log.parent.handlers
>> _does_ have them.
>> 
>> A few options to fix this:
>> 
>> - I can add an explicit handler for .task.raw in my logging config.
>> - We can always call set_context on airflow.task instead of
>> airflow.task.raw
>> - We walk up the .parent links if .propagate is True (possibly stopping
>> once we find any handlers)
>> 
>> -ash
>> 
>> 
>>> On 30 Nov 2017, at 16:02, Ash Berlin-Taylor <ash_airflowlist@firemirror.
>> com> wrote:
>>> 
>>> I'm fairly sure I'm back to stock config now. Here is the DAG I am
>> testing with:
>>> 
>>> from datetime import datetime
>>> from airflow import DAG
>>> from airflow.operators.python_operator import PythonOperator
>>> 
>>> dag_args = {
>>>   "start_date": datetime(2017, 11, 20),
>>> }
>>> dag = DAG("tests", default_args=dag_args)
>>> 
>>> 
>>> def print_stuff(ti, **kwargs):
>>>   print("Hi from", __file__)
>>>   ti.log.error("Hello")
>>> 
>>> with dag:
>>>   PythonOperator(
>>>       task_id="test-logging",
>>>       dag=dag,
>>>       python_callable=print_stuff,
>>>       provide_context=True,
>>>   )
>>> 
>>> 
>>> And I don't see either of the "Hi from" or "Hello" lines in the
>> resulting log file. I have edited airflow/logging_config.py to print the
>> config before it uses it, and this is the config I'm getting:
>>> 
>>> {'disable_existing_loggers': False,
>>> 'formatters': {'airflow.processor': {'format': '[%(asctime)s] '
>>> 
>> '{%(filename)s:%(lineno)d} '
>>>                                               '%(levelname)s -
>> %(message)s'},
>>>               'airflow.task': {'format': '[%(asctime)s] '
>>>                                          '{%(filename)s:%(lineno)d} '
>>>                                          '%(levelname)s -
>> %(message)s'}},
>>> 'handlers': {'console': {'class': 'logging.StreamHandler',
>>>                         'formatter': 'airflow.task',
>>>                         'stream': 'ext://sys.stdout'},
>>>             'file.processor': {'base_log_folder':
>> '/usr/local/airflow/logs/scheduler',
>>>                                'class': 'airflow.utils.log.file_
>> processor_handler.FileProcessorHandler',
>>>                                'filename_template': '{{ filename
>> }}.log',
>>>                                'formatter': 'airflow.processor'},
>>>             'file.task': {'base_log_folder': '/usr/local/airflow/logs/',
>>>                           'class': 'airflow.utils.log.file_task_
>> handler.FileTaskHandler',
>>>                           'filename_template': '{{ ti.dag_id }}/{{ '
>>>                                                'ti.task_id }}/{{ ts
>> }}/{{ '
>>>                                                'try_number }}.log',
>>>                           'formatter': 'airflow.task'}},
>>> 'loggers': {'': {'handlers': ['console'], 'level': 'INFO'},
>>>            'airflow': {'handlers': ['console'],
>>>                        'level': 'INFO',
>>>                        'propagate': False},
>>>            'airflow.processor': {'handlers': ['file.processor'],
>>>                                  'level': 'INFO',
>>>                                  'propagate': True},
>>>            'airflow.task': {'handlers': ['file.task'],
>>>                             'level': 'INFO',
>>>                             'propagate': False},
>>>            'airflow.task_runner': {'handlers': ['file.task'],
>>>                                    'level': 'INFO',
>>>                                    'propagate': True}},
>>> 
>>> 
>>> If I edit run() in in bin/cli.py to print the log.handlers under this
>> circumstance I get an empty list [].
>>> 
>>> I guess since we don't specify 'airflow.task.raw' in the loggers that it
>> should go up to the next level in 'airflow.task'? Except it doesn't seem to
>> be for me. I'm digging further.
>>> 
>>> -ash
>>> 
>>> 
>>> 
>>>> On 30 Nov 2017, at 15:38, Bolke de Bruin <bdbruin@gmail.com> wrote:
>>>> 
>>>> airflow.task.raw points to airflow.task by default, which does have a
>> handler and that is the one that is travelled. And yes we know the code is
>> incorrect in this area, but the default does work correctly.
>>>> 
>>>> Bolke.
>>>> 
>>>> 
>>>>> On 30 Nov 2017, at 16:27, Ash Berlin-Taylor <
>> ash_airflowlist@firemirror.com> wrote:
>>>>> 
>>>>> Okay I think the problem (if not the cause) is around here:
>> https://github.com/apache/incubator-airflow/blob/master/
>> airflow/bin/cli.py#L366-L376
>>>>> 
>>>>> 
>>>>> 
>>>>> log = logging.getLogger('airflow.task')
>>>>> if args.raw:
>>>>> log = logging.getLogger('airflow.task.raw')
>>>>> 
>>>>> for handler in log.handlers:
>>>>> try:
>>>>>     handler.set_context(ti)
>>>>> except AttributeError:
>>>>>     # Not all handlers need to have context passed in so we ignore
>>>>>     # the error when handlers do not have set_context defined.
>>>>> pass
>>>>> 
>>>>> The problem seems to be that airflow.task.raw is no longer configured
>> explicitly, so it's log.handlers is an empty list.
>>>>> 
>>>>> This in turn means that any log calls end up not writing anything as
>> our FileTaskHandler's self.handler property is None, meaning it doesn't
>> emit anything.
>>>>> 
>>>>> Does this ring any bells to anyone?
>>>>> 
>>>>> 
>>>>>> On 30 Nov 2017, at 15:18, Ash Berlin-Taylor <
>> ash_airflowlist@firemirror.com> wrote:
>>>>>> 
>>>>>> Hmmm is anyone else seeing logs from inside operators? Right now
>> we're not getting any logs out of operators. I'm in the process of
>> debugging to work out if it's our logging config or something in Airflow,
>> but right now I don't seem to get any output from the operator itself,
>> neither print(), or `ti.log.info()`
>>>>>> 
>>>>>> Anyone else noticed similar, or is it something specific to our
>> environment?
>>>>>> 
>>>>>> -ash
>>>>>> 
>>>>>>> On 30 Nov 2017, at 09:52, Ash Berlin-Taylor <
>> ash_airflowlist@firemirror.com> wrote:
>>>>>>> 
>>>>>>> We're running more tests (day of meetings meant we couldn't do
as
>> many as I'd have liked yesterday) but looking good so far.
>>>>>>> 
>>>>>>> +0.5 (non binding)
>>>>>>> 
>>>>>>> -ash
>>>>>>> 
>>>>>>>> On 29 Nov 2017, at 18:31, Chris Riccomini <criccomini@apache.org>
>> wrote:
>>>>>>>> 
>>>>>>>> Anyone else? Last day before I close the vote off.
>>>>>>>> 
>>>>>>>> On Mon, Nov 27, 2017 at 12:32 PM, Driesprong, Fokko
>> <fokko@driesprong.frl>
>>>>>>>> wrote:
>>>>>>>> 
>>>>>>>>> +1
>>>>>>>>> 
>>>>>>>>> Op ma 27 nov. 2017 om 21:24 schreef Bolke de Bruin <
>> bdbruin@gmail.com>
>>>>>>>>> 
>>>>>>>>>> +1, binding
>>>>>>>>>> 
>>>>>>>>>> Let’s get it out!
>>>>>>>>>> 
>>>>>>>>>> Sent from my iPhone
>>>>>>>>>> 
>>>>>>>>>>> On 27 Nov 2017, at 20:32, Chris Riccomini <criccomini@apache.org
>>> 
>>>>>>>>> wrote:
>>>>>>>>>>> 
>>>>>>>>>>> Hey all,
>>>>>>>>>>> 
>>>>>>>>>>> I have cut Airflow 1.9.0 RC4. This email is calling
a vote on the
>>>>>>>>>> release,
>>>>>>>>>>> which will last for 72 hours. Consider this my
(binding) +1.
>>>>>>>>>>> 
>>>>>>>>>>> Airflow 1.9.0 RC4 is available at:
>>>>>>>>>>> 
>>>>>>>>>>> https://dist.apache.org/repos/dist/dev/incubator/airflow/1.
>> 9.0rc4/
>>>>>>>>>>> 
>>>>>>>>>>> apache-airflow-1.9.0rc4+incubating-source.tar.gz
is a source
>> release
>>>>>>>>> that
>>>>>>>>>>> comes with INSTALL instructions.
>>>>>>>>>>> apache-airflow-1.9.0rc4+incubating-bin.tar.gz
is the binary
>> Python
>>>>>>>>>> "sdist"
>>>>>>>>>>> release.
>>>>>>>>>>> 
>>>>>>>>>>> Public keys are available at:
>>>>>>>>>>> 
>>>>>>>>>>> https://dist.apache.org/repos/dist/release/incubator/airflow/
>>>>>>>>>>> 
>>>>>>>>>>> The release contains the following JIRAs:
>>>>>>>>>>> 
>>>>>>>>>>> *https://issues.apache.org/jira/browse/AIRFLOW-1839
>>>>>>>>>>> <https://issues.apache.org/jira/browse/AIRFLOW-1839>*
>>>>>>>>>>> 
>>>>>>>>>>> Along with all JIRAs that were in 1.9.0RC3 (see
previous VOTE
>> email for
>>>>>>>>>>> full list).
>>>>>>>>>>> 
>>>>>>>>>>> Cheers,
>>>>>>>>>>> Chris
>>>>>>>>>> 
>>>>>>>>> 
>>>>>>> 
>>>>>> 
>>>>> 
>>>> 
>>> 
>> 
>> 


Mime
View raw message