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 <[email protected]> > 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 >>>>>>>>>>>>>>> >>>>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>> >>>>>>>>> >>>>>>>> >>>>>>> >>>>>>> >>>>> >>>>> >>> >>> >
