[AIRFLOW-6460] Reduce timeout in pytest

[mik-laj]

Hello

I am not sure, but I suspect that when the test is marked as flaky, the time without writing to the console exceed the Travis limits, because maximum time is performed repeatedly, and in the meantime, nothing is written on the screen. Unfortunately, after 10 minutes Travis stops the job.

I suggest drastically reducing this timeout . This will also prevent the introduction of a test that would slow down our CI. I chose the value of 90 seconds based on the list of slowest tests (available below). The slowest test takes 50s, so 90 seconds is a sensible value. Travis CI can sometimes be overloaded, so 50 seconds can be dangerous.

========================== slowest 100 test durations ==========================
50.11s call     tests/cli/commands/test_task_command.py::TestCliTaskBackfill::test_run_ignores_all_dependencies
40.59s call     tests/providers/amazon/aws/hooks/test_lambda_function.py::TestAwsLambdaHook::test_invoke_lambda_function
27.42s call     tests/cli/commands/test_dag_command.py::TestCliDags::test_next_execution
25.06s call     tests/executors/test_celery_executor.py::TestCeleryExecutor::test_celery_integration_1_redis_redis_6379_0
25.05s call     tests/test_impersonation.py::TestImpersonation::test_impersonation_subdag
21.00s call     tests/test_impersonation.py::TestImpersonationWithCustomPythonPath::test_impersonation_custom
19.71s call     tests/test_impersonation.py::TestImpersonation::test_default_impersonation
19.68s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_run_backwards
19.04s call     tests/test_impersonation.py::TestImpersonation::test_no_impersonation
17.84s call     tests/test_impersonation.py::TestImpersonation::test_impersonation
17.22s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_trigger_controller_dag
15.07s call     tests/sensors/test_timeout_sensor.py::TestSensorTimeout::test_timeout
12.32s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_with_requirements_pinned
12.26s call     tests/cli/commands/test_webserver_command.py::TestCliWebServer::test_cli_webserver_shutdown_when_gunicorn_master_is_killed
11.83s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_system_site_packages
11.75s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_python_3
10.15s call     tests/executors/test_celery_executor.py::TestCeleryExecutor::test_celery_integration_0_amqp_guest_guest_rabbitmq_5672
9.91s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_depends_on_past_backwards
8.57s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_context
8.20s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_with_args
8.19s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_nonimported_as_arg
8.16s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_fail
8.15s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_no_requirements
8.14s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_return_none
6.58s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_max_limit_check
6.49s call     tests/test_core.py::TestCore::test_terminate_task
6.40s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_max_limit_check_complete_loop
6.16s call     tests/test_core.py::TestCore::test_task_fail_duration
6.13s call     tests/jobs/test_scheduler_job.py::TestSchedulerJob::test_retry_still_in_executor
6.11s call     tests/jobs/test_local_task_job.py::TestLocalTaskJob::test_heartbeat_failed_fast
6.10s call     tests/hooks/test_druid_hook.py::TestDruidHook::test_submit_timeout
6.01s call     tests/kubernetes/test_pod_launcher.py::TestPodLauncher::test_read_pod_logs_retries_fails
6.01s call     tests/kubernetes/test_pod_launcher.py::TestPodLauncher::test_read_pod_retries_fails
5.82s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_depends_on_past
5.58s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_range_requirements
5.57s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_no_system_site_packages
5.55s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_unpinned_requirements
5.12s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_examples_0_example_branch_operator
5.06s call     tests/sensors/test_http_sensor.py::TestHttpSensor::test_logging_head_error_request
4.99s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_python_2
4.57s call     tests/jobs/test_scheduler_job.py::TestSchedulerJob::test_scheduler_start_date
4.48s call     tests/jobs/test_scheduler_job.py::TestSchedulerJob::test_dag_with_system_exit
4.48s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_python_2_7
4.29s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_without_dill
4.20s call     tests/jobs/test_scheduler_job.py::TestSchedulerJob::test_new_import_error_replaces_old
4.18s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_ordered_concurrent_execute
4.15s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_respect_task_concurrency_limit
4.15s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_respect_pool_limit
4.15s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_respect_default_pool_limit
4.14s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_respect_dag_concurrency_limit
4.13s call     tests/cli/commands/test_role_command.py::TestCliRoles::test_cli_create_roles
4.04s call     tests/jobs/test_scheduler_job.py::TestSchedulerJob::test_scheduler_reschedule
4.01s call     tests/contrib/sensors/test_sagemaker_training_sensor.py::TestSageMakerTrainingSensor::test_sensor_with_log
4.01s call     tests/contrib/sensors/test_sagemaker_training_sensor.py::TestSageMakerTrainingSensor::test_sensor
4.01s call     tests/contrib/sensors/test_sagemaker_transform_sensor.py::TestSageMakerTransformSensor::test_sensor
4.01s call     tests/contrib/sensors/test_sagemaker_tuning_sensor.py::TestSageMakerTuningSensor::test_sensor
3.59s call     tests/cli/commands/test_task_command.py::TestCliTasks::test_cli_list_tasks
3.58s call     tests/hooks/test_hive_hook.py::TestHiveCliHook::test_run_cli
3.56s call     tests/jobs/test_scheduler_job.py::TestSchedulerJob::test_remove_error_clears_import_error
3.43s call     tests/operators/test_virtualenv_operator.py::TestPythonVirtualenvOperator::test_string_args
3.26s call     tests/jobs/test_scheduler_job.py::TestSchedulerJob::test_scheduler_task_start_date
3.25s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_rerun_upstream_failed_tasks
3.24s call     tests/models/test_taskinstance.py::TestTaskInstance::test_retry_delay
3.21s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_max_limit_check_no_count_existing
3.20s call     tests/task/task_runner/test_standard_task_runner.py::TestStandardTaskRunner::test_on_kill
3.18s call     tests/hooks/test_hive_hook.py::TestHiveMetastoreHook::test_check_for_named_partition
3.18s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_multi_dates
3.14s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_max_limit_check_within_limit
3.14s call     tests/www/test_views.py::TestLogView::test_get_logs_with_metadata_for_removed_dag
3.12s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_examples_2_example_skip_dag
3.11s call     tests/www/test_views.py::TestLogView::test_get_file_task_log_1_up_for_retry
3.10s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_examples_1_example_bash_operator
3.10s call     tests/test_core.py::TestCore::test_bash_operator_kill
3.03s call     tests/cli/commands/test_webserver_command.py::TestCLIGetNumReadyWorkersRunning::test_cli_webserver_debug
3.01s call     tests/contrib/hooks/test_sagemaker_hook.py::TestSageMakerHook::test_training_with_logs
3.01s call     tests/contrib/hooks/test_sagemaker_hook.py::TestSageMakerHook::test_training_throws_error_when_failed_with_wait
3.01s call     tests/contrib/hooks/test_sagemaker_hook.py::TestSageMakerHook::test_training_ends_with_wait
2.69s call     tests/www/test_views.py::TestLogView::test_get_logs_with_metadata
2.61s call     tests/www/api/experimental/test_dag_runs_endpoint.py::TestDagRunsEndpoint::test_get_dag_runs_no_runs
2.59s call     tests/www/test_views.py::TestLogView::test_get_file_task_log_4_running
2.56s call     tests/www/test_views.py::TestLogView::test_get_file_task_log_0
2.55s call     tests/www/api/experimental/test_endpoints.py::TestPoolApiExperimental::test_get_pool
2.54s call     tests/cli/commands/test_user_command.py::TestCliUsers::test_cli_add_user_role
2.52s call     tests/www/api/experimental/test_endpoints.py::TestApiExperimental::test_info
2.51s call     tests/www/test_views.py::TestLogView::test_get_file_task_log_3_up_for_reschedule
2.50s call     tests/www/test_views.py::TestLogView::test_get_file_task_log_2_up_for_reschedule
2.50s call     tests/www/test_views.py::TestLogView::test_get_file_task_log_6_failed
2.49s call     tests/serialization/test_dag_serialization.py::TestStringifiedDAGs::test_deserialization
2.49s call     tests/www/test_views.py::TestLogView::test_get_file_task_log_5_success
2.48s setup    tests/test_config_templates.py::TestAirflowCfg::test_should_be_ascii_file_0_default_airflow_cfg
2.48s setup    tests/www/test_views.py::TestDagRunModelView::test_create_dagrun
2.43s call     tests/hooks/test_hive_hook.py::TestHiveServer2Hook::test_get_pandas_df
2.42s setup    tests/www/test_views.py::TestAirflowBaseViews::test_blocked
2.36s call     tests/jobs/test_backfill_job.py::TestBackfillJob::test_backfill_run_rescheduled
2.35s call     tests/www/api/experimental/test_dag_runs_endpoint.py::TestDagRunsEndpoint::test_get_dag_runs_invalid_dag_id
2.33s call     tests/www/test_views.py::TestLogView::test_get_logs_with_null_metadata
2.32s call     tests/www/test_views.py::TestLogView::test_get_logs_with_metadata_as_download_large_file
2.31s call     tests/www/test_views.py::TestLogView::test_get_logs_with_metadata_as_download_file
2.30s call     tests/www/test_views.py::TestDagACLView::test_blocked_success
2.28s call     tests/cli/commands/test_user_command.py::TestCliUsers::test_cli_remove_user_role

---

Link to JIRA issue: https://issues.apache.org/jira/browse/AIRFLOW-6460

• Description above provides context of the change
• Commit message starts with [AIRFLOW-NNNN], where AIRFLOW-NNNN = JIRA ID*
• Unit tests coverage for changes (not needed for documentation changes)
• Commits follow "How to write a good git commit message"
• Relevant documentation is updated including usage instructions.
• I will engage committers as explained in Contribution Workflow Example.

(*) For document-only changes, no JIRA issue is needed. Commit message starts [AIRFLOW-XXXX].

---

In case of fundamental code change, Airflow Improvement Proposal (AIP) is needed.
In case of a new dependency, check compliance with the ASF 3rd Party License Policy.
In case of backwards incompatible changes please leave a note in UPDATING.md.
Read the Pull Request Guidelines for more information.

[tooptoop4]

@mik-laj is 90s too short?

I consistently hit this in travis:
tests/test_impersonation.py ..Timeout (0:01:30)!
2519Thread 0x00007f7793263700 (most recent call first):
2520 File "/usr/local/lib/python3.7/threading.py", line 296 in wait
2521 File "/usr/local/lib/python3.7/queue.py", line 170 in get
2522 File "/usr/local/lib/python3.7/site-packages/cassandra/cluster.py", line 3609 in run
2523 File "/usr/local/lib/python3.7/site-packages/sentry_sdk/integrations/threading.py", line 67 in run
2524 File "/usr/local/lib/python3.7/threading.py", line 926 in _bootstrap_inner
2525 File "/usr/local/lib/python3.7/threading.py", line 890 in _bootstrap
2526
2527Thread 0x00007f77a38ac700 (most recent call first):
2528 File "/usr/local/lib/python3.7/site-packages/MySQLdb/connections.py", line 280 in query
2529 File "/usr/local/lib/python3.7/site-packages/MySQLdb/cursors.py", line 378 in _query
2530 File "/usr/local/lib/python3.7/site-packages/MySQLdb/cursors.py", line 252 in execute
2531 File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 581 in do_execute
2532 File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 1246 in _execute_context
2533 File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 1101 in _execute_clauseelement
2534 File "/usr/local/lib/python3.7/site-packages/sqlalchemy/sql/elements.py", line 287 in _execute_on_connection
2535 File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 982 in execute
2536 File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/query.py", line 3392 in _execute_and_instances
2537 File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/query.py", line 3367 in iter
2538 File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/query.py", line 3043 in getitem
2539 File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/query.py", line 3265 in first
2540 File "/opt/airflow/airflow/models/taskinstance.py", line 446 in refresh_from_db
2541 File "/opt/airflow/airflow/utils/session.py", line 61 in wrapper
2542 File "/opt/airflow/airflow/jobs/backfill_job.py", line 190 in _update_counters
2543 File "/opt/airflow/airflow/jobs/backfill_job.py", line 611 in _process_backfill_task_instances
2544 File "/opt/airflow/airflow/utils/session.py", line 57 in wrapper
2545 File "/opt/airflow/airflow/jobs/backfill_job.py", line 718 in _execute_for_run_dates
2546 File "/opt/airflow/airflow/utils/session.py", line 57 in wrapper
2547 File "/opt/airflow/airflow/jobs/backfill_job.py", line 787 in _execute
2548 File "/opt/airflow/airflow/utils/session.py", line 61 in wrapper
2549 File "/opt/airflow/airflow/jobs/base_job.py", line 215 in run
2550 File "/opt/airflow/tests/test_impersonation.py", line 136 in run_backfill
2551 File "/opt/airflow/tests/test_impersonation.py", line 182 in test_impersonation_subdag
2552 File "/usr/local/lib/python3.7/unittest/case.py", line 628 in run
2553 File "/usr/local/lib/python3.7/unittest/case.py", line 676 in call
2554 File "/usr/local/lib/python3.7/site-packages/_pytest/unittest.py", line 207 in runtest
2555 File "/usr/local/lib/python3.7/site-packages/_pytest/runner.py", line 131 in pytest_runtest_call
2556 File "/usr/local/lib/python3.7/site-packages/pluggy/callers.py", line 187 in _multicall
2557 File "/usr/local/lib/python3.7/site-packages/pluggy/manager.py", line 87 in
2558 File "/usr/local/lib/python3.7/site-packages/pluggy/manager.py", line 93 in _hookexec
2559 File "/usr/local/lib/python3.7/site-packages/pluggy/hooks.py", line 286 in call
2560 File "/usr/local/lib/python3.7/site-packages/_pytest/runner.py", line 207 in
2561 File "/usr/local/lib/python3.7/site-packages/_pytest/runner.py", line 234 in from_call
2562 File "/usr/local/lib/python3.7/site-packages/_pytest/runner.py", line 207 in call_runtest_hook
2563 File "/usr/local/lib/python3.7/site-packages/flaky/flaky_pytest_plugin.py", line 129 in call_and_report
2564 File "/usr/local/lib/python3.7/site-packages/_pytest/runner.py", line 96 in runtestprotocol
2565 File "/usr/local/lib/python3.7/site-packages/_pytest/runner.py", line 81 in pytest_runtest_protocol
2566 File "/usr/local/lib/python3.7/site-packages/flaky/flaky_pytest_plugin.py", line 92 in pytest_runtest_protocol
2567 File "/usr/local/lib/python3.7/site-packages/pluggy/callers.py", line 187 in _multicall
2568 File "/usr/local/lib/python3.7/site-packages/pluggy/manager.py", line 87 in
2569 File "/usr/local/lib/python3.7/site-packages/pluggy/manager.py", line 93 in _hookexec
2570 File "/usr/local/lib/python3.7/site-packages/pluggy/hooks.py", line 286 in call
2571 File "/usr/local/lib/python3.7/site-packages/_pytest/main.py", line 270 in pytest_runtestloop
2572 File "/usr/local/lib/python3.7/site-packages/pluggy/callers.py", line 187 in _multicall
2573 File "/usr/local/lib/python3.7/site-packages/pluggy/manager.py", line 87 in
2574 File "/usr/local/lib/python3.7/site-packages/pluggy/manager.py", line 93 in _hookexec
2575 File "/usr/local/lib/python3.7/site-packages/pluggy/hooks.py", line 286 in call
2576 File "/usr/local/lib/python3.7/site-packages/_pytest/main.py", line 246 in _main
2577 File "/usr/local/lib/python3.7/site-packages/_pytest/main.py", line 196 in wrap_session
2578 File "/usr/local/lib/python3.7/site-packages/_pytest/main.py", line 239 in pytest_cmdline_main
2579 File "/usr/local/lib/python3.7/site-packages/pluggy/callers.py", line 187 in _multicall
2580 File "/usr/local/lib/python3.7/site-packages/pluggy/manager.py", line 87 in
2581 File "/usr/local/lib/python3.7/site-packages/pluggy/manager.py", line 93 in _hookexec
2582 File "/usr/local/lib/python3.7/site-packages/pluggy/hooks.py", line 286 in call
2583 File "/usr/local/lib/python3.7/site-packages/_pytest/config/init.py", line 92 in main
2584 File "/usr/local/bin/pytest", line 10 in

[potiuk]

Yep @tooptoop4 -> I reverted it and also added #7064 to show errors immediately when they happen (that is actually the problem this timeout decrease tried to address).