[AIRFLOW-1385] Make Airflow task logging configurable

[allisonwang]

Dear Airflow maintainers,

Please accept this PR. I understand that it will not be reviewed until I have checked off all the steps below!

JIRA

• My PR addresses Airflow 1385 and references them in the PR title.

Description

• Here are some details about my PR, including screenshots of any UI changes:

This PR adds configurable task logging to Airflow. Please refer to #2422 for previous discussions. This is the first step of making entire Airflow logging configurable (AIRFLOW-1454).

Tests

• My PR adds the following unit tests OR does not need testing for this extremely good reason:

FileTaskHandler is tested locally and in staging. S3TaskHandler is tested in staging. GCSTaskHandler is not tested.

Commits

• My commits all reference JIRA issues in their subject lines, and I have squashed multiple commits if they address the same issue. In addition, my commits follow the guidelines from "How to write a good git commit message":
  1. Subject is separated from body by a blank line
  2. Subject is limited to 50 characters
  3. Subject does not end with a period
  4. Subject uses the imperative mood ("add", not "adding")
  5. Body wraps at 72 characters
  6. Body explains "what" and "why", not "how"

[mention-bot]

@allisonwang, thanks for your PR! By analyzing the history of the files in this pull request, we identified @mistercrunch, @aoen and @bolkedebruin to be potential reviewers.

[codecov-io]

Codecov Report

Merging #2464 into master will increase coverage by 0.12%.
The diff coverage is 59.27%.

@@            Coverage Diff             @@
##           master    #2464      +/-   ##
==========================================
+ Coverage   69.95%   70.07%   +0.12%     
==========================================
  Files         146      150       +4     
  Lines       11448    11538      +90     
==========================================
+ Hits         8008     8085      +77     
- Misses       3440     3453      +13

Impacted Files	Coverage Δ
airflow/task_runner/base_task_runner.py	72.88% <100%> (+0.46%)	⬆️
airflow/utils/logging.py	54.78% <33.33%> (-4.05%)	⬇️
airflow/utils/log/s3_task_handler.py	37.5% <37.5%> (ø)
airflow/utils/log/gcs_task_handler.py	41.17% <41.17%> (ø)
airflow/www/views.py	69.78% <46.66%> (+2.21%)	⬆️
airflow/bin/cli.py	51.74% <70%> (-1.23%)	⬇️
airflow/utils/log/file_task_handler.py	71.23% <71.23%> (ø)
...irflow/config_templates/default_airflow_logging.py	85.71% <85.71%> (ø)
airflow/settings.py	88.88% <88.88%> (ø)	⬆️
... and 5 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update fa84d49...f175c4a. Read the comment docs.

[bolkedebruin]

does task_instance have this number implicitly?

[allisonwang]

Yes but we need to fetch logs given different try_number. task_instance record only has the number of latest attempt.

[bolkedebruin]

From a design point of view this is unclean. task_instance is an instantiation of a task in time. As such it is bound to a try_number, which is now also provides.

I suggest to change the signature of the method to def read(self, task_instance, try_number=None) and the return the latest log if try_number isn't specified or maybe even better all logs. This also makes it easier if we would like to integrate this with the Rest API.

Or, use a different signature all together def read(self, task, execution_date, try_number).

On a side note: the try_number thing still feels a bit off. Properly keeping track of start_dates (i.e. recording each start_date somewhere) seems more logical. try_number in the end is the count of start_dates.

[allisonwang]

task_instance signature alone is definitely not enough, as we need to fetch logs from different previous try_number. Using try_number=None and return all logs separated by try_number sounds good.

Regarding the side note, try_number is definitely not ideal, as we need a better way to distinguish each task instance attempt. Right now try_number is used as a supplement to its primary key dag_id, task_id and execution_date to make each task attempt unique. In the future, we might need to change the db schema and use other fields as task_instance primary key.

[allisonwang]

@bolkedebruin Is there major thing in PR that needs to be changed? If not, I will iterate more quickly on this PR and hopefully modify the ElasticSearch PR to use this new logging framework. I will add GCS and make a list of JIRA tasks for subsequent improvements.

[bolkedebruin]

No not directly. Please create the Jira to track the the outstanding (particularly GCS as people rely on it). Then squash the commits one into so we can merge it and iterate from there.

As mentioned in the other PR I'm getting more and more convinced that try_number is not the right approach, but we can work that out later.

I'm really happy with this PR as it lays out the right foundation. It isn't perfect, but a lot better than what we had. So good job ;-), keep it up.

[allisonwang]

@bolkedebruin PTAL. GCS Task handler is added and read method signature is slightly changed. I've created a JIRA AIRFLOW-1454 and several sub-tasks for improving airflow logging. Please feel free to modify and/or add more tasks.

[saguziel]

Let's use hasattr instead

[saguziel]

It's more explicit

[allisonwang]

https://hynek.me/articles/hasattr This article points out using hasattr in Python 2 can be harmful since it shadows errors in properties. In this case it's probably fine for now to use hasattr but it doesn't seem to be a good practice to use in Python 2.

[saguziel]

Nice catch. Feel free to leave as is

[saguziel]

Why have the catchall? I think if there's an exception we should just let it happen.

"Fail loudly"

[allisonwang]

Hmm it should still work if users don't have their own logging config right? Will change the exception to be more specific.

[saguziel]

We should at least say something? Isn't there a default logging config. My worry is that when a config doesn't import correctly it will silently use the default, which is bad.

[saguziel]

better to say is not None

[saguziel]

maybe log something about the exception?

[allisonwang]

Thos are all direct copy paste from original code but I will add exception message as it can be really useful.

[saguziel]

also print exception here

[saguziel]

maybe log something?, explain why pass

[allisonwang]

This is part of the refactor from the original code. Some of the logic might need to be changed, such as mkdir. I feel it's better to change in a separate PR, but I will definitely make a note here.

[saguziel]

Ah, ok makes sense

[saguziel]

is GCS misplaced text here?

[saguziel]

nvm

[saguziel]

Multiline comment instead?

[allisonwang]

Also part of refactored code. This part, as well as this comment, should be changed in the future.

[saguziel]

S3log?

[saguziel]

use hasattr

[saguziel]

either that or make that method exist no matter what and let loggers decide whether to use it or not

[allisonwang]

Same as above comment for hasattr. Standard Python handlers won't have set_context so the method can't exist for all methods. It's worth thinking what's the best way to set logger context without breaking the abstraction for python log handlers.

[saguziel]

Sounds good

[bolkedebruin]

Why no time pull this from the logging config, can be global (in the dict) but seems to be tight to a Handler

[allisonwang]

Oh this specifies the filename of the user defined logging configuration if they do not want to use the default default_airflow_logging.py. It's like specifying the path for this config file.

[bolkedebruin]

Gotcha

[bolkedebruin]

Let's pull this from the config dict, you could even template it

[bolkedebruin]

I know this is old code, but why do we check if it exists on the local system while we can just compare host names? I.e. If the local host name is not equal to task instance host name we should pull from remote

[allisonwang]

My understanding is that checking hostname is not enough. There is only one task instance record with dag_id, task_id and execution date in DB. Once task re-attempts, the hostname information might be updated. So even if the task instance currently has hostname A, it could still have older logs in machine B or C that got wiped out when DB updates. So this local machine might have older logs.

Direct updating on top of existing DB records in generally makes things much harder to keep track. I would prefer having another table to keep track of task_instance changes.

[bolkedebruin]

For future, I think task_instance and try_number should be enough to pull from remote.

[allisonwang]

what exactly does this worker_log_server_port do? If we remove it here would different workers be able to access each other's local disk to fetch logs?

[bolkedebruin]

It is the port the logs will be made available on with a simple web server

[bolkedebruin]

Let's do this with a template for this handler

[bolkedebruin]

I.e. No hardcore .log

[allisonwang]

@bolkedebruin I added some unit tests for dictConfig and file task handler. It's hard to test S3 and/or GCS for correct behaviors. Is there a mock lib for testing those? (maybe I can use moto)

[bolkedebruin]

@ronfung can you help out with the GCS part? Or ask Chris?

@allisonwang I think you can use boto/boto3 (check which is the current one, the S3 operators use it) for S3. I don't have too much cloud exposure myself as I can't use it.

[criccomini]

I'm fine merging the GCS changes into master. We can fix forward when 1.9.0 test/stable is cut.

[criccomini]

I took a brief look and everything seems reasonable.

@jgao54 do you want to try this patch out and verify that GCS works?

[bolkedebruin]

@criccomini we are looking for how to test the logic on Travis. Ie the question is how can we test it without having a GCS account? Can we mock it?

[criccomini]

Got it. I looked a long time ago, but couldn't find any good GCS mock solutions. In the absence of that, you're left just mocking the APIs, which really doesn't test much at all.

I did some googling, and I still haven't found a Python mock that will let you simulate GCS locally, so traditional mocks would be all we have left. Again, that really doesn't test that match, but it's better than nothing, I suppose.

[allisonwang]

@bolkedebruin I tried testing using moto, the testing lib for mocking AWS and boto3, but it doesn't work well with current S3_Hook as it requires passing in s3 connection object. Current S3Log instantiates using only connection id so mocking s3 doesn't work in this case. This PR #2499 adds S3 log tests using mock which looks good to me. I will test S3 on our production environment and 'mock' to make sure it works.

[bolkedebruin]

Overall looks good and just some minor nits. Can you
:
0. Address the nits and comments

1. Make the tests pass so we can have a look at the coverage
2. Add documentation on how to configure logging
3. Squash your commits

I presume you would like to have

[bolkedebruin]

Why is this not a child of airflow.task? It would not require to repeat the same config

[allisonwang]

@bolkedebruin Task runner in current structure is under module Airflow not airflow.task. It uses a LoggingMixin that gets the corresponding logger with the module name. We can make another folder called under airflow/task and put task runner inside if needed. But we can always reorganize the folder structure later.

[bolkedebruin]

Ok. Leave it for now then

[bolkedebruin]

Can you mirror the the logging setup? Ie. The test file should mirror the file you are Testing against.

[allisonwang]

Oops need to rebase and fix the test conflicts.

[bolkedebruin]

Can you make this 444 instead? There is no need to have these files executable. (Yes I know it was there before, it is still a security concern)

[allisonwang]

This is definitely a concern but I prefer creating another JIRA and make the change in another PR. There are some reasons why 666 is needed (it breaks the system otherwise). Dan can probably explain more. I will add a TODO here.

[bolkedebruin]

@aoen why the executable bit?

[bolkedebruin]

@allisonwang ok

[aoen]

Allison's last day will be the 11th but there are some other bits of administrivia that she needs to spend some time on. I'm trying to keep the scope down of this task because I really want to see it ship (there were a couple of other logging refactor attempts that fizzled out). To that effort I think we shouldn't try to keep most of the behavior/functionality the same as it might cause unexpected bugs that need to be fixed (e.g. with subdags).

[bolkedebruin]

@aoen ok fully understood and I agree. Besides I think it won't be required to do this anyway, if we let tasks log to stdout and let the log file be handled by the LocalTaskJob as I mentioned earlier.

[bolkedebruin]

I think this is good to merge. If you still have a bit of time @allisonwang please increase coverage of the FileTaskHandler (the read method seems untested ).

@allisonwang really good job on getting this through. You were challenged on the first approach, but took it on nevertheless. I think it got a lot better because of it and it has become a foundation that we can build on. Let me know if you want to spent some time in Amsterdam ;-).

+1

( I can't test the patch myself as I am not in the country, just baby sitting this one through. So I am assuming you guys tested it)

[allisonwang]

@bolkedebruin Thanks for reviewing this PR! I've tested the file handler and s3 handler in our staging environment (but not GCS handler). Feel free to pin me if there are issues and I am happy to fix them in the future :)

I will add documentations soon in another PR.

[bolkedebruin]

@aoen can you please merge? I cannot from my current location

[aoen]

I would be more than happy to!

[aoen]