[AIRFLOW-1423] Add logs to the scheduler DAG run decision logic

[ultrabug]

One of the most frustrating topic for users is usually related
to their understanding on the scheduler decisions about running
a DAG or not.

It would be wise to add more logs in the jobs creation decision
so that it gets more clear whether a DAG is run or not and why.

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 the following Airflow JIRA issues and references them in the PR title. For example, "[AIRFLOW-1423] My Airflow PR"
  • https://issues.apache.org/jira/browse/AIRFLOW-1423

Description

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

One of the most frustrating topic for users is usually related to their understanding on the scheduler decisions about running a DAG or not.

It would be wise to add more logs in the jobs creation decision so that it gets more clear whether a DAG is run or not and why.

This patch adds such simple and useful logs.

Tests

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

Logs only

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"

[codecov-io]

Codecov Report

Merging #2455 into master will increase coverage by 0.04%.
The diff coverage is 81.81%.

@@            Coverage Diff             @@
##           master    #2455      +/-   ##
==========================================
+ Coverage    69.4%   69.44%   +0.04%     
==========================================
  Files         146      146              
  Lines       11289    11298       +9     
==========================================
+ Hits         7835     7846      +11     
+ Misses       3454     3452       -2

Impacted Files	Coverage Δ
airflow/jobs.py	76.73% <81.81%> (+0.39%)	⬆️

---

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 751e936...b68b8f2. Read the comment docs.

[bolkedebruin]

info level plz

[saguziel]

Same comment as above everywhere ( put dag_id here)

[bolkedebruin]

debug level plz

[bolkedebruin]

debug level plz

[bolkedebruin]

debug level plz

[bolkedebruin]

debug lvl plz

[bolkedebruin]

debug lvl please

[saguziel]

Put dag name and runs in the message too

[ultrabug]

@saguziel I did not put the dag_id in any of the logs to remain in line with the other logs and also because they are already split by their dag name.

Do you still want me to do this? If so, would you like all logs to include the dag_id to remain consistent?

[ultrabug]

Thanks for your reply @bolkedebruin but I really think this is worth an INFO log level since it's crucial to understand the decision making of the scheduler in production environment.

[saguziel]

probably should be is not None

[ultrabug]

right, good point

[ultrabug]

sorry, actually it's is None instead, committing

[ultrabug]

@bolkedebruin @saguziel I've updated the PR with requested changes.

[bolkedebruin]

@ultrabug I disagree with your assessment of the requirement for the high log levels. The scheduler is already quite chatty. Please lower the levels.

[ultrabug]

@bolkedebruin okay, can we settle to at least keep the last one (next scheduled execution time) to info? This one is very valuable.

Thanks in advance

[bolkedebruin]

Sure no problem.

[ultrabug]

@bolkedebruin done, thanks.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[ron819]

@ultrabug was there something else needs to be done in this PR ?

[ultrabug]

@ron819 well AFAIK I've done what has been asked for me but ofc now there are conflicts..

I'd be more happy to see #2460 getting attention tho, since it gives a better user experience over this kind of information

[mik-laj]

Such formatting of messages causes that a string object is created, which then may not be used anywhere, when the login level will be too low.
Formatting parameters should be passed as arguments to the info method.
Example:

self.log.info("The Table '%s' does not exists already.", self.table_id)
```

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[OmerJog]

@mik-laj Is the format the only issue here?
This PR is standing for a while and it's just about logging :/
I'm willing to re-PR if @ultrabug has no time but lets first decide if we want this change in.
No reason to hang PRs if the functionality is disputed

[ultrabug]

@OmerJog I'll happily update this PR shall it be acknowledged first indeed.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[ultrabug]

@mik-laj @bolkedebruin @saguziel will be happy to correct anything if there's a chance it gets some attention, answer would be appreciated thanks.

If not, please close this PR yourself so we at least know where we stand.

Cheers mates.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.