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