Ill have a patch in an hour or so
> On 30 Nov 2017, at 19:28, Chris Riccomini <[email protected]> wrote: > > K, I'm going to let this vote hang here until we get confirmation as to > what's going on. > > @bolke/@ash, thanks for looking into this! > > On Thu, Nov 30, 2017 at 10:23 AM, Bolke de Bruin <[email protected]> wrote: > >> Ok, I think I can confirm the issue. I don’t see any output either with a >> clean install. I’ll investigate a bit further. >> >> *sigh* >> >> Bolke >> >> >>> On 30 Nov 2017, at 19:13, Ash Berlin-Taylor <ash_airflowlist@firemirror. >> com> wrote: >>> >>> Yes, that is in my logging config. >>> >>> I think I agree about airflow.task.raw >>> >>> -ash >>> >>> >>>> On 30 Nov 2017, at 18:06, Joy Gao <[email protected]> wrote: >>>> >>>> Hi Ash, >>>> >>>> Can you verify that your logging config has root logger set to >> 'console'? >>>> Something like: >>>> >>>> '': { >>>> 'handlers': ['console'], >>>> 'level': LOG_LEVEL >>>> }, >>>> >>>> >>>> That was the issue we had because we attempted to set *all* handlers to >>>> airflow.task at first. >>>> >>>> I don't think we gain anything by calling airflow.task.raw logger, so I >>>> have a pending PR that removes airflow.task.raw and just uses >> airflow.task. >>>> >>>> >>>> >>>> On Thu, Nov 30, 2017 at 9:24 AM, Bolke de Bruin <[email protected]> >> wrote: >>>> >>>>> We saw this issue around RC2, so I’m surprised that it turns up again. >> We >>>>> discussed it at lengths with Fokko and Joy. It might be that we somehow >>>>> missed a commit, but I need to double check a from stock install. We >> are >>>>> running 1.9 in production and we don’t have any logging issues. >>>>> >>>>> B. >>>>> >>>>> Verstuurd vanaf mijn iPad >>>>> >>>>>> Op 30 nov. 2017 om 18:17 heeft Chris Riccomini <[email protected] >>> >>>>> het volgende geschreven: >>>>>> >>>>>> @bolke/@fokko, thoughts? >>>>>> >>>>>> As an aside, we had an issue seeing task logs, but were able to fix >> it by >>>>>> modifying our logging config (and perhaps patching some stuff that we >>>>>> merged into 1.9.0, don't recall). William Pursell/Joy Gao might be >> able >>>>> to >>>>>> comment more. >>>>>> >>>>>> On Thu, Nov 30, 2017 at 9:08 AM, Ash Berlin-Taylor < >>>>>> [email protected]> wrote: >>>>>> >>>>>>> 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 <[email protected]> >>>>> 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 < >>>>>>>> [email protected]> 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 <[email protected]> >> 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 < >>>>>>>>> [email protected]> 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 < >>>>>>>>> [email protected]> 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 < >>>>>>>>> [email protected]> 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 < >>>>> [email protected]> >>>>>>>>> wrote: >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> Anyone else? Last day before I close the vote off. >>>>>>>>>>>>>>> >>>>>>>>>>>>>>> On Mon, Nov 27, 2017 at 12:32 PM, Driesprong, Fokko >>>>>>>>> <[email protected]> >>>>>>>>>>>>>>> wrote: >>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> +1 >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> Op ma 27 nov. 2017 om 21:24 schreef Bolke de Bruin < >>>>>>>>> [email protected]> >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>> +1, binding >>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>> Let’s get it out! >>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>> Sent from my iPhone >>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>>>> On 27 Nov 2017, at 20:32, Chris Riccomini < >>>>>>> [email protected] >>>>>>>>>> >>>>>>>>>>>>>>>> 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 >>>>>>>>>>>>>>>>> >>>>>>>>>>>>>>>> >>>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>> >>>>>>> >>>>> >>>>> >>> >> >>
