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 >>>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>> >>>>>>>>> >>>>>>>> >>>>>>> >>>>>> >>>>>> >>>> >>>> >> >>
