<h3 dir="auto">Apache Airflow version</h3>
<p dir="auto">2.2.3 (latest released)</p>
<h3 dir="auto">What happened</h3>
<p dir="auto">I followed all the instructions to set up Breeze for the first time but when I run <code class="notranslate">./breeze</code> I get the following error:</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="#10 9.605 
#10 9.605 Installing mysql client version 8.0
#10 9.605 
#10 9.613 gpg: keybox '/tmp/tmp.u3jwOIxYZN/pubring.kbx' created
#10 12.79 gpg: keyserver receive failed: No keyserver available
#10 22.83 gpg: keyserver receive failed: Server indicated a failure
#10 58.88 gpg: keyserver receive failed: No name
#10 58.88 gpg: keyserver receive failed: No keyserver available
#10 58.89 gpg: WARNING: nothing exported
#10 58.90 deb http://repo.mysql.com/apt/debian/ buster mysql-8.0
#10 59.04 Get:1 http://security.debian.org/debian-security buster/updates InRelease [65.4 kB]
#10 59.04 Get:2 http://deb.debian.org/debian buster InRelease [122 kB]
#10 59.06 Get:3 http://repo.mysql.com/apt/debian buster InRelease [22.1 kB]
#10 59.15 Get:4 https://dl.yarnpkg.com/debian stable InRelease [17.1 kB]
#10 59.15 Get:5 https://deb.nodesource.com/node_14.x buster InRelease [4584 B]
#10 59.18 Get:6 http://deb.debian.org/debian buster-updates InRelease [51.9 kB]
#10 59.29 Err:3 http://repo.mysql.com/apt/debian buster InRelease
#10 59.29   The following signatures couldn't be verified because the public key is not available: NO_PUBKEY 467B942D3A79BD29
#10 59.47 Get:7 http://security.debian.org/debian-security buster/updates/main amd64 Packages [313 kB]
#10 59.56 Get:8 https://deb.nodesource.com/node_14.x buster/main amd64 Packages [770 B]
#10 59.71 Get:9 http://deb.debian.org/debian buster/main amd64 Packages [7906 kB]
#10 59.95 Get:10 https://dl.yarnpkg.com/debian stable/main amd64 Packages [10.5 kB]
#10 60.00 Get:11 https://dl.yarnpkg.com/debian stable/main all Packages [10.5 kB]
#10 60.20 Get:12 http://deb.debian.org/debian buster-updates/main amd64 Packages [8792 B]
#10 61.30 Reading package lists...
#10 62.13 W: GPG error: http://repo.mysql.com/apt/debian buster InRelease: The following signatures couldn't be verified because the public key is not available: NO_PUBKEY 467B942D3A79BD29
#10 62.13 E: The repository 'http://repo.mysql.com/apt/debian buster InRelease' is not signed.
#10 62.13 W: Target Packages (mysql-8.0/binary-amd64/Packages) is configured multiple times in /etc/apt/sources.list.d/mysql.list:1 and /etc/apt/sources.list.d/mysql.list:2
#10 62.13 W: Target Packages (mysql-8.0/binary-all/Packages) is configured multiple times in /etc/apt/sources.list.d/mysql.list:1 and /etc/apt/sources.list.d/mysql.list:2
------
error: failed to solve: executor failed running [/bin/bash -o pipefail -o errexit -o nounset -o nolog -c chmod a+x /scripts/docker/install_mysql.sh /scripts/docker/install_mssql.sh     &amp;&amp; sync      &amp;&amp; /scripts/docker/install_mysql.sh prod      &amp;&amp; /scripts/docker/install_mysql.sh dev      &amp;&amp; /scripts/docker/install_mssql.sh     &amp;&amp; adduser --gecos &quot;First Last,RoomNumber,WorkPhone,HomePhone&quot; --disabled-password               --quiet &quot;airflow&quot; --home &quot;/home/airflow&quot;     &amp;&amp; echo -e &quot;airflow\nairflow&quot; | passwd airflow 2&gt;&amp;1     &amp;&amp; echo &quot;airflow ALL=(ALL) NOPASSWD: ALL&quot; &gt; /etc/sudoers.d/airflow     &amp;&amp; chmod 0440 /etc/sudoers.d/airflow]: exit code: 100"><pre class="notranslate"><code class="notranslate">#10 9.605 
#10 9.605 Installing mysql client version 8.0
#10 9.605 
#10 9.613 gpg: keybox '/tmp/tmp.u3jwOIxYZN/pubring.kbx' created
#10 12.79 gpg: keyserver receive failed: No keyserver available
#10 22.83 gpg: keyserver receive failed: Server indicated a failure
#10 58.88 gpg: keyserver receive failed: No name
#10 58.88 gpg: keyserver receive failed: No keyserver available
#10 58.89 gpg: WARNING: nothing exported
#10 58.90 deb http://repo.mysql.com/apt/debian/ buster mysql-8.0
#10 59.04 Get:1 http://security.debian.org/debian-security buster/updates InRelease [65.4 kB]
#10 59.04 Get:2 http://deb.debian.org/debian buster InRelease [122 kB]
#10 59.06 Get:3 http://repo.mysql.com/apt/debian buster InRelease [22.1 kB]
#10 59.15 Get:4 https://dl.yarnpkg.com/debian stable InRelease [17.1 kB]
#10 59.15 Get:5 https://deb.nodesource.com/node_14.x buster InRelease [4584 B]
#10 59.18 Get:6 http://deb.debian.org/debian buster-updates InRelease [51.9 kB]
#10 59.29 Err:3 http://repo.mysql.com/apt/debian buster InRelease
#10 59.29   The following signatures couldn't be verified because the public key is not available: NO_PUBKEY 467B942D3A79BD29
#10 59.47 Get:7 http://security.debian.org/debian-security buster/updates/main amd64 Packages [313 kB]
#10 59.56 Get:8 https://deb.nodesource.com/node_14.x buster/main amd64 Packages [770 B]
#10 59.71 Get:9 http://deb.debian.org/debian buster/main amd64 Packages [7906 kB]
#10 59.95 Get:10 https://dl.yarnpkg.com/debian stable/main amd64 Packages [10.5 kB]
#10 60.00 Get:11 https://dl.yarnpkg.com/debian stable/main all Packages [10.5 kB]
#10 60.20 Get:12 http://deb.debian.org/debian buster-updates/main amd64 Packages [8792 B]
#10 61.30 Reading package lists...
#10 62.13 W: GPG error: http://repo.mysql.com/apt/debian buster InRelease: The following signatures couldn't be verified because the public key is not available: NO_PUBKEY 467B942D3A79BD29
#10 62.13 E: The repository 'http://repo.mysql.com/apt/debian buster InRelease' is not signed.
#10 62.13 W: Target Packages (mysql-8.0/binary-amd64/Packages) is configured multiple times in /etc/apt/sources.list.d/mysql.list:1 and /etc/apt/sources.list.d/mysql.list:2
#10 62.13 W: Target Packages (mysql-8.0/binary-all/Packages) is configured multiple times in /etc/apt/sources.list.d/mysql.list:1 and /etc/apt/sources.list.d/mysql.list:2
------
error: failed to solve: executor failed running [/bin/bash -o pipefail -o errexit -o nounset -o nolog -c chmod a+x /scripts/docker/install_mysql.sh /scripts/docker/install_mssql.sh     &amp;&amp; sync      &amp;&amp; /scripts/docker/install_mysql.sh prod      &amp;&amp; /scripts/docker/install_mysql.sh dev      &amp;&amp; /scripts/docker/install_mssql.sh     &amp;&amp; adduser --gecos "First Last,RoomNumber,WorkPhone,HomePhone" --disabled-password               --quiet "airflow" --home "/home/airflow"     &amp;&amp; echo -e "airflow\nairflow" | passwd airflow 2&gt;&amp;1     &amp;&amp; echo "airflow ALL=(ALL) NOPASSWD: ALL" &gt; /etc/sudoers.d/airflow     &amp;&amp; chmod 0440 /etc/sudoers.d/airflow]: exit code: 100
</code></pre></div>
<p dir="auto">I am not sure what steps to take to resolve this for Breeze.</p>
<p dir="auto">It seems related to <a href="https://github.com/apache/airflow/issues/20911" data-hovercard-type="issue" data-hovercard-url="/apache/airflow/issues/20911/hovercard">20911</a> but the install script appears to have the new key</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="#!/usr/bin/env bash
# Licensed to the Apache Software Foundation (ASF) under one
# or more contributor license agreements.  See the NOTICE file
# distributed with this work for additional information
# regarding copyright ownership.  The ASF licenses this file
# to you under the Apache License, Version 2.0 (the
# &quot;License&quot;); you may not use this file except in compliance
# with the License.  You may obtain a copy of the License at
#
#   http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing,
# software distributed under the License is distributed on an
# &quot;AS IS&quot; BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
# KIND, either express or implied.  See the License for the
# specific language governing permissions and limitations
# under the License.
set -euo pipefail
declare -a packages

MYSQL_VERSION=&quot;8.0&quot;
readonly MYSQL_VERSION

COLOR_BLUE=$'\e[34m'
readonly COLOR_BLUE
COLOR_RESET=$'\e[0m'
readonly COLOR_RESET

: &quot;${INSTALL_MYSQL_CLIENT:?Should be true or false}&quot;

install_mysql_client() {
    echo
    echo &quot;${COLOR_BLUE}Installing mysql client version ${MYSQL_VERSION}${COLOR_RESET}&quot;
    echo

    if [[ &quot;${1}&quot; == &quot;dev&quot; ]]; then
        packages=(&quot;libmysqlclient-dev&quot; &quot;mysql-client&quot;)
    elif [[ &quot;${1}&quot; == &quot;prod&quot; ]]; then
        packages=(&quot;libmysqlclient21&quot; &quot;mysql-client&quot;)
    else
        echo
        echo &quot;Specify either prod or dev&quot;
        echo
        exit 1
    fi

    local key=&quot;467B942D3A79BD29&quot;
    readonly key

    GNUPGHOME=&quot;$(mktemp -d)&quot;
    export GNUPGHOME
    set +e
    for keyserver in $(shuf -e ha.pool.sks-keyservers.net hkp://p80.pool.sks-keyservers.net:80 \
                               keyserver.ubuntu.com hkp://keyserver.ubuntu.com:80)
    do
        gpg --keyserver &quot;${keyserver}&quot; --recv-keys &quot;${key}&quot; 2&gt;&amp;1 &amp;&amp; break
    done
    set -e
    gpg --export &quot;${key}&quot; &gt; /etc/apt/trusted.gpg.d/mysql.gpg
    gpgconf --kill all
    rm -rf &quot;${GNUPGHOME}&quot;
    unset GNUPGHOME
    echo &quot;deb http://repo.mysql.com/apt/debian/ buster mysql-${MYSQL_VERSION}&quot; | tee -a /etc/apt/sources.list.d/mysql.list
    apt-get update
    apt-get install --no-install-recommends -y &quot;${packages[@]}&quot;
    apt-get autoremove -yqq --purge
    apt-get clean &amp;&amp; rm -rf /var/lib/apt/lists/*
}

# Install MySQL client from Oracle repositories (Debian installs mariadb)
# But only if it is not disabled
if [[ ${INSTALL_MYSQL_CLIENT:=&quot;true&quot;} == &quot;true&quot; ]]; then
    install_mysql_client &quot;${@}&quot;
fi
"><pre class="notranslate"><code class="notranslate">#!/usr/bin/env bash
# Licensed to the Apache Software Foundation (ASF) under one
# or more contributor license agreements.  See the NOTICE file
# distributed with this work for additional information
# regarding copyright ownership.  The ASF licenses this file
# to you under the Apache License, Version 2.0 (the
# "License"); you may not use this file except in compliance
# with the License.  You may obtain a copy of the License at
#
#   http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing,
# software distributed under the License is distributed on an
# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
# KIND, either express or implied.  See the License for the
# specific language governing permissions and limitations
# under the License.
set -euo pipefail
declare -a packages

MYSQL_VERSION="8.0"
readonly MYSQL_VERSION

COLOR_BLUE=$'\e[34m'
readonly COLOR_BLUE
COLOR_RESET=$'\e[0m'
readonly COLOR_RESET

: "${INSTALL_MYSQL_CLIENT:?Should be true or false}"

install_mysql_client() {
    echo
    echo "${COLOR_BLUE}Installing mysql client version ${MYSQL_VERSION}${COLOR_RESET}"
    echo

    if [[ "${1}" == "dev" ]]; then
        packages=("libmysqlclient-dev" "mysql-client")
    elif [[ "${1}" == "prod" ]]; then
        packages=("libmysqlclient21" "mysql-client")
    else
        echo
        echo "Specify either prod or dev"
        echo
        exit 1
    fi

    local key="467B942D3A79BD29"
    readonly key

    GNUPGHOME="$(mktemp -d)"
    export GNUPGHOME
    set +e
    for keyserver in $(shuf -e ha.pool.sks-keyservers.net hkp://p80.pool.sks-keyservers.net:80 \
                               keyserver.ubuntu.com hkp://keyserver.ubuntu.com:80)
    do
        gpg --keyserver "${keyserver}" --recv-keys "${key}" 2&gt;&amp;1 &amp;&amp; break
    done
    set -e
    gpg --export "${key}" &gt; /etc/apt/trusted.gpg.d/mysql.gpg
    gpgconf --kill all
    rm -rf "${GNUPGHOME}"
    unset GNUPGHOME
    echo "deb http://repo.mysql.com/apt/debian/ buster mysql-${MYSQL_VERSION}" | tee -a /etc/apt/sources.list.d/mysql.list
    apt-get update
    apt-get install --no-install-recommends -y "${packages[@]}"
    apt-get autoremove -yqq --purge
    apt-get clean &amp;&amp; rm -rf /var/lib/apt/lists/*
}

# Install MySQL client from Oracle repositories (Debian installs mariadb)
# But only if it is not disabled
if [[ ${INSTALL_MYSQL_CLIENT:="true"} == "true" ]]; then
    install_mysql_client "${@}"
fi

</code></pre></div>
<h3 dir="auto">What you expected to happen</h3>
<p dir="auto"><em>No response</em></p>
<h3 dir="auto">How to reproduce</h3>
<p dir="auto"><em>No response</em></p>
<h3 dir="auto">Operating System</h3>
<p dir="auto">MacOS version 10.15.7</p>
<h3 dir="auto">Versions of Apache Airflow Providers</h3>
<p dir="auto"><em>No response</em></p>
<h3 dir="auto">Deployment</h3>
<p dir="auto">Docker-Compose</p>
<h3 dir="auto">Deployment details</h3>
<p dir="auto"><em>No response</em></p>
<h3 dir="auto">Anything else</h3>
<p dir="auto"><em>No response</em></p>
<h3 dir="auto">Are you willing to submit PR?</h3>
<ul class="contains-task-list">
<li class="task-list-item"><input type="checkbox" id="" disabled="" class="task-list-item-checkbox"> Yes I am willing to submit a PR!</li>
</ul>
<h3 dir="auto">Code of Conduct</h3>
<ul class="contains-task-list">
<li class="task-list-item"><input type="checkbox" id="" disabled="" class="task-list-item-checkbox" checked=""> I agree to follow this project's <a href="https://github.com/apache/airflow/blob/main/CODE_OF_CONDUCT.md">Code of Conduct</a></li>
</ul>
<p dir="auto"><strong>Apache Airflow version</strong>: 2.1.3</p>
<p dir="auto"><strong>Apache Airflow Provider versions</strong> (please include all providers that are relevant to your bug):</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="apache-airflow-providers-amazon==2.0.0
apache-airflow-providers-celery==2.0.0
apache-airflow-providers-cncf-kubernetes==2.0.0
apache-airflow-providers-docker==2.0.0
apache-airflow-providers-elasticsearch==2.0.2
apache-airflow-providers-ftp==2.0.0
apache-airflow-providers-google==4.0.0
apache-airflow-providers-grpc==2.0.0
apache-airflow-providers-hashicorp==2.0.0
apache-airflow-providers-http==2.0.0
apache-airflow-providers-imap==2.0.0
apache-airflow-providers-microsoft-azure==3.0.0
apache-airflow-providers-mysql==2.0.0
apache-airflow-providers-postgres==2.0.0
apache-airflow-providers-redis==2.0.0
apache-airflow-providers-sendgrid==2.0.0
apache-airflow-providers-sftp==2.0.0
apache-airflow-providers-slack==4.0.0
apache-airflow-providers-sqlite==2.0.0
apache-airflow-providers-ssh==2.0.0"><pre class="notranslate"><code class="notranslate">apache-airflow-providers-amazon==2.0.0
apache-airflow-providers-celery==2.0.0
apache-airflow-providers-cncf-kubernetes==2.0.0
apache-airflow-providers-docker==2.0.0
apache-airflow-providers-elasticsearch==2.0.2
apache-airflow-providers-ftp==2.0.0
apache-airflow-providers-google==4.0.0
apache-airflow-providers-grpc==2.0.0
apache-airflow-providers-hashicorp==2.0.0
apache-airflow-providers-http==2.0.0
apache-airflow-providers-imap==2.0.0
apache-airflow-providers-microsoft-azure==3.0.0
apache-airflow-providers-mysql==2.0.0
apache-airflow-providers-postgres==2.0.0
apache-airflow-providers-redis==2.0.0
apache-airflow-providers-sendgrid==2.0.0
apache-airflow-providers-sftp==2.0.0
apache-airflow-providers-slack==4.0.0
apache-airflow-providers-sqlite==2.0.0
apache-airflow-providers-ssh==2.0.0
</code></pre></div>
<p dir="auto"><strong>Environment</strong>:</p>
<p dir="auto">I'm using the <a class="issue-link js-issue-link notranslate" rel="noopener noreferrer nofollow" href="https://issues.apache.org/jira/browse/AIRFLOW-2">airflow-2</a>.1.2 container from dockerhub.</p>
<ul dir="auto">
<li><strong>Cloud provider or hardware configuration</strong>: AWS</li>
<li><strong>OS</strong> (e.g. from /etc/os-release): <code class="notranslate">Debian GNU/Linux 10 (buster)</code></li>
<li><strong>Kernel</strong> (e.g. <code class="notranslate">uname -a</code>): <code class="notranslate">Linux fe52079d9ade 5.12.13-200.fc33.x86_64 #1 SMP Wed Jun 23 16:20:26 UTC 2021 x86_64 GNU/Linux</code></li>
</ul>
<p dir="auto"><strong>What happened</strong>:</p>
<p dir="auto">When using the EMRStepSensor (set to reschedule mode) to monitor EMR steps, the task will sometimes fail while the EMR step sucessfully ran. Most of the time the sensor will work fine, but every so often this issue occurs (on the same DAG, without modifications).</p>
<details>
<summary>EMRStepSensor task instance debug log</summary>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="*** Reading local file: /opt/airflow/logs/derived.adobe_target_catalog_sporza/watch_adobe_target_catalog_sporza_job_emr_step/2021-08-07T05:28:00+00:00/1.log
[2021-08-08 05:29:20,367] {__init__.py:51} DEBUG - Loading core task runner: StandardTaskRunner
[2021-08-08 05:29:21,594] {base_task_runner.py:62} DEBUG - Planning to run as the  user
[2021-08-08 05:29:21,597] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; from DB
[2021-08-08 05:29:22,086] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:29:22,086] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:29:22,086] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Instance State' PASSED: True, Task state queued was valid.
[2021-08-08 05:29:22,128] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:29:22,128] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:29:22,129] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Instance Not Running' PASSED: True, Task is not in running state.
[2021-08-08 05:29:22,130] {taskinstance.py:896} INFO - Dependencies all met for &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:29:22,130] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:29:22,165] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:29:22,206] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:29:22,327] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Pool Slots Available' PASSED: True, ('There are enough open slots in %s to execute the task', 'default_pool')
[2021-08-08 05:29:22,327] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Concurrency' PASSED: True, Task concurrency is not set.
[2021-08-08 05:29:22,327] {taskinstance.py:896} INFO - Dependencies all met for &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:29:22,327] {taskinstance.py:1087} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:29:22,327] {taskinstance.py:1088} INFO - Starting attempt 1 of 1
[2021-08-08 05:29:22,327] {taskinstance.py:1089} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:29:24,417] {taskinstance.py:1107} INFO - Executing &lt;Task(EmrStepSensor): watch_adobe_target_catalog_sporza_job_emr_step&gt; on 2021-08-07T05:28:00+00:00
[2021-08-08 05:29:24,421] {standard_task_runner.py:52} INFO - Started process 7426 to run task
[2021-08-08 05:29:24,427] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', 'derived.adobe_target_catalog_sporza', 'watch_adobe_target_catalog_sporza_job_emr_step', '2021-08-07T05:28:00+00:00', '--job-id', '98940', '--pool', 'default_pool', '--raw', '--subdir', 'DAGS_FOLDER/adobe_target_catalog_sporza_wf.py', '--cfg-path', '/tmp/tmpucsqr5ep', '--error-file', '/tmp/tmpi1wh32jz']
[2021-08-08 05:29:24,427] {standard_task_runner.py:77} INFO - Job 98940: Subtask watch_adobe_target_catalog_sporza_job_emr_step
[2021-08-08 05:29:24,428] {cli_action_loggers.py:66} DEBUG - Calling callbacks: [&lt;function default_action_log at 0x7fc8dfbe5d90&gt;]
[2021-08-08 05:29:26,223] {settings.py:208} DEBUG - Setting up DB connection pool (PID 7426)
[2021-08-08 05:29:26,223] {settings.py:244} DEBUG - settings.prepare_engine_args(): Using NullPool
[2021-08-08 05:29:26,226] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [None]&gt; from DB
[2021-08-08 05:29:27,030] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:29:27,523] {logging_mixin.py:104} INFO - Running &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; on host ip-172-31-58-121.eu-west-1.compute.internal
[2021-08-08 05:29:27,523] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:29:28,218] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:29:28,871] {taskinstance.py:677} DEBUG - Clearing XCom data
[2021-08-08 05:29:29,515] {taskinstance.py:684} DEBUG - XCom data cleared
[2021-08-08 05:29:32,916] {taskinstance.py:1302} INFO - Exporting the following env vars:
AIRFLOW_CTX_DAG_OWNER=vrt
AIRFLOW_CTX_DAG_ID=derived.adobe_target_catalog_sporza
AIRFLOW_CTX_TASK_ID=watch_adobe_target_catalog_sporza_job_emr_step
AIRFLOW_CTX_EXECUTION_DATE=2021-08-07T05:28:00+00:00
AIRFLOW_CTX_DAG_RUN_ID=scheduled__2021-08-07T05:28:00+00:00
[2021-08-08 05:29:32,916] {__init__.py:146} DEBUG - Preparing lineage inlets and outlets
[2021-08-08 05:29:32,916] {__init__.py:190} DEBUG - inlets: [], outlets: []
[2021-08-08 05:29:33,486] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:29:36,437] {base_aws.py:368} INFO - Airflow Connection: aws_conn_id=aws_default
[2021-08-08 05:29:36,521] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:29:36,562] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:29:38,654] {base_aws.py:179} INFO - No credentials retrieved from Connection
[2021-08-08 05:29:38,654] {base_aws.py:87} INFO - Creating session with aws_access_key_id=None region_name=None
[2021-08-08 05:29:38,655] {hooks.py:417} DEBUG - Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
[2021-08-08 05:29:38,656] {hooks.py:417} DEBUG - Changing event name from before-call.apigateway to before-call.api-gateway
[2021-08-08 05:29:38,657] {hooks.py:417} DEBUG - Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
[2021-08-08 05:29:38,659] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
[2021-08-08 05:29:38,659] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.route53 to before-parameter-build.route-53
[2021-08-08 05:29:38,659] {hooks.py:417} DEBUG - Changing event name from request-created.cloudsearchdomain.Search to request-created.cloudsearch-domain.Search
[2021-08-08 05:29:38,660] {hooks.py:417} DEBUG - Changing event name from docs.*.autoscaling.CreateLaunchConfiguration.complete-section to docs.*.auto-scaling.CreateLaunchConfiguration.complete-section
[2021-08-08 05:29:38,663] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.logs.CreateExportTask to before-parameter-build.cloudwatch-logs.CreateExportTask
[2021-08-08 05:29:38,663] {hooks.py:417} DEBUG - Changing event name from docs.*.logs.CreateExportTask.complete-section to docs.*.cloudwatch-logs.CreateExportTask.complete-section
[2021-08-08 05:29:38,663] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.cloudsearchdomain.Search to before-parameter-build.cloudsearch-domain.Search
[2021-08-08 05:29:38,663] {hooks.py:417} DEBUG - Changing event name from docs.*.cloudsearchdomain.Search.complete-section to docs.*.cloudsearch-domain.Search.complete-section
[2021-08-08 05:29:38,664] {base_aws.py:157} INFO - role_arn is None
[2021-08-08 05:29:38,667] {utils.py:364} DEBUG - IMDS ENDPOINT: http://169.254.169.254/
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: env
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: assume-role
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: assume-role-with-web-identity
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: sso
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: shared-credentials-file
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: custom-process
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: config-file
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: ec2-credentials-file
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: boto-config
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: container-role
[2021-08-08 05:29:38,671] {connectionpool.py:230} DEBUG - Starting new HTTP connection (1): 169.254.170.2:80
[2021-08-08 05:29:38,673] {connectionpool.py:442} DEBUG - http://169.254.170.2:80 &quot;GET /v2/credentials/c5f7099a-d46e-4472-a48f-6c137db9e75d HTTP/1.1&quot; 200 1307
[2021-08-08 05:29:38,674] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/endpoints.json
[2021-08-08 05:29:38,683] {hooks.py:210} DEBUG - Event choose-service-name: calling handler &lt;function handle_service_name_alias at 0x7fc8dbee8bf8&gt;
[2021-08-08 05:29:38,691] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/emr/2009-03-31/service-2.json
[2021-08-08 05:29:38,695] {hooks.py:210} DEBUG - Event creating-client-class.emr: calling handler &lt;function add_generate_presigned_url at 0x7fc8dbf947b8&gt;
[2021-08-08 05:29:38,697] {endpoint.py:292} DEBUG - Setting elasticmapreduce timeout as (60, 60)
[2021-08-08 05:29:38,698] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/_retry.json
[2021-08-08 05:29:38,698] {client.py:166} DEBUG - Registering retry handlers for service: emr
[2021-08-08 05:29:38,699] {emr_step.py:73} INFO - Poking step s-581MKMYKRED7 on cluster j-XDTNJDHR23RQ
[2021-08-08 05:29:38,699] {hooks.py:210} DEBUG - Event before-parameter-build.emr.DescribeStep: calling handler &lt;function generate_idempotent_uuid at 0x7fc8dbf06048&gt;
[2021-08-08 05:29:38,699] {hooks.py:210} DEBUG - Event before-call.emr.DescribeStep: calling handler &lt;function inject_api_version_header_if_needed at 0x7fc8dbf077b8&gt;
[2021-08-08 05:29:38,699] {endpoint.py:101} DEBUG - Making request for OperationModel(name=DescribeStep) with params: {'url_path': '/', 'query_string': '', 'method': 'POST', 'headers': {'X-Amz-Target': 'ElasticMapReduce.DescribeStep', 'Content-Type': 'application/x-amz-json-1.1', 'User-Agent': 'Boto3/1.17.107 Python/3.6.13 Linux/4.14.238-182.422.amzn2.x86_64 exec-env/AWS_ECS_FARGATE Botocore/1.20.107'}, 'body': b'{&quot;ClusterId&quot;: &quot;j-XDTNJDHR23RQ&quot;, &quot;StepId&quot;: &quot;s-581MKMYKRED7&quot;}', 'url': 'https://eu-west-1.elasticmapreduce.amazonaws.com/', 'context': {'client_region': 'eu-west-1', 'client_config': &lt;botocore.config.Config object at 0x7fc8dba19470&gt;, 'has_streaming_input': False, 'auth_type': None}}
[2021-08-08 05:29:38,700] {hooks.py:210} DEBUG - Event request-created.emr.DescribeStep: calling handler &lt;bound method RequestSigner.handler of &lt;botocore.signers.RequestSigner object at 0x7fc8dba19438&gt;&gt;
[2021-08-08 05:29:38,700] {hooks.py:210} DEBUG - Event choose-signer.emr.DescribeStep: calling handler &lt;function set_operation_specific_signer at 0x7fc8dbf01ea0&gt;
[2021-08-08 05:29:38,700] {auth.py:380} DEBUG - Calculating signature using v4 auth.
[2021-08-08 05:29:38,700] {auth.py:381} DEBUG - CanonicalRequest:
POST
/

content-type:application/x-amz-json-1.1
host:eu-west-1.elasticmapreduce.amazonaws.com
x-amz-date:20210808T052938Z
x-amz-security-token:IQoJb3JpZ2luX2VjEGwaCWV1LXdlc3QtMSJHMEUCIQCZ4NXI3+3YJKZwyu+L4vTyY4swRSd7+zHkDO3Nwc0JiwIgdDuzR2+qJ5vFE03B1RRhzZYGV4Iy/pt7jVXRr0YjXTUqogQIhP//////////ARABGgwyODM3NzQxNDgzNTciDDl+9YdFHetmruZnfSr2A4vFCZwFNe0LEigdz0ayjIhvTZMsjY6CClml27JRBbUllyWz6t3b5SjafRWERgfEe1xIjnFFvp/UFSDIrZVuOefX94uUcgWQKV5zhz/dHdpCzpPltF+syapd2IeY5lgaUZWr+ax+Pfs75JILyfTpa7u43hg1M6P9L07zP/IUWdrXvyvu0wVh07r6/bHUDKJGy52Ok2q6Hr4ltT4MVAY/EZIEDZA8dlNdd7/UDddecp+/7/QIMftzZsgQJVyO+IIB+cfHCIV+1g/ACnsSbBkJuH2fn/B0YeP6e1135yTFknzNKVUxf6OeBIuPrkcu78HnaOXcjv+JSKb9AcFP+2zOo9JYmr040XGVqesZiAc+uDWbL74LDQ7ze5b4sLSNXfCCEvqsYVy9Nt7UlopCXoIS2lBrWgXNhsppDQ976Gr+WgyV1Wbjx2NZlJFCtSNarwF0qDPBmm6yhQxyKMYarOrUpy9aNl/18ujIhJZ2/JMUYlzH0TOBc1YCKIuZLNPwYfxZW6JmosfKXjAFUK7eDn4tU6LSXyo2GNLYzjY71OyCOpllJYtxg/NDAQBlmMCbFPpFCCTjPECU0sGnhfPAdlsyYngT3L0bSyjAZpPRfYrfPd4i3j2niPq9BwF/iOIR95T2CK7zqxXB4TIpporSE0pItmFgynGTh+IwtZm9iAY6pgENShKQaHxJvNj1O5ddYeCwW3H2SqjrHroeOt82xGkH5stZ7g28Uy7iPIPEehlkrB7ry/KjLq9DAo4zVneHhfKJBUBTBxz944AZhd0d9VvSRGgEXnmxzTsHma9hnkwQfGdbXwH4ja582o7hPEI98AAgoo5OCuV/vyMHHgrJBa7z+7eRtGnCeg+EJZy9WlsilHHGze4QGDEDc4NJypNZM4JON503hXON
x-amz-target:ElasticMapReduce.DescribeStep

content-type;host;x-amz-date;x-amz-security-token;x-amz-target
2a131454435119560c6fa09b6b1eeeb557aba91e61af62fe4883ccc24890c4f3
[2021-08-08 05:29:38,700] {auth.py:383} DEBUG - StringToSign:
AWS4-HMAC-SHA256
20210808T052938Z
20210808/eu-west-1/elasticmapreduce/aws4_request
29f0d229d76daf02f334b8c7d193cb06de4619f4adb7b3057683f53b2ea79c80
[2021-08-08 05:29:38,700] {auth.py:385} DEBUG - Signature:
66e13f874221cb3c1b275a052ac56a7e827d431e940bfe9b14414104e0a3b162
[2021-08-08 05:29:38,701] {endpoint.py:187} DEBUG - Sending http request: &lt;AWSPreparedRequest stream_output=False, method=POST, url=https://eu-west-1.elasticmapreduce.amazonaws.com/, headers={'X-Amz-Target': b'ElasticMapReduce.DescribeStep', 'Content-Type': b'application/x-amz-json-1.1', 'User-Agent': b'Boto3/1.17.107 Python/3.6.13 Linux/4.14.238-182.422.amzn2.x86_64 exec-env/AWS_ECS_FARGATE Botocore/1.20.107', 'X-Amz-Date': b'20210808T052938Z', 'X-Amz-Security-Token': b'IQoJb3JpZ2luX2VjEGwaCWV1LXdlc3QtMSJHMEUCIQCZ4NXI3+3YJKZwyu+L4vTyY4swRSd7+zHkDO3Nwc0JiwIgdDuzR2+qJ5vFE03B1RRhzZYGV4Iy/pt7jVXRr0YjXTUqogQIhP//////////ARABGgwyODM3NzQxNDgzNTciDDl+9YdFHetmruZnfSr2A4vFCZwFNe0LEigdz0ayjIhvTZMsjY6CClml27JRBbUllyWz6t3b5SjafRWERgfEe1xIjnFFvp/UFSDIrZVuOefX94uUcgWQKV5zhz/dHdpCzpPltF+syapd2IeY5lgaUZWr+ax+Pfs75JILyfTpa7u43hg1M6P9L07zP/IUWdrXvyvu0wVh07r6/bHUDKJGy52Ok2q6Hr4ltT4MVAY/EZIEDZA8dlNdd7/UDddecp+/7/QIMftzZsgQJVyO+IIB+cfHCIV+1g/ACnsSbBkJuH2fn/B0YeP6e1135yTFknzNKVUxf6OeBIuPrkcu78HnaOXcjv+JSKb9AcFP+2zOo9JYmr040XGVqesZiAc+uDWbL74LDQ7ze5b4sLSNXfCCEvqsYVy9Nt7UlopCXoIS2lBrWgXNhsppDQ976Gr+WgyV1Wbjx2NZlJFCtSNarwF0qDPBmm6yhQxyKMYarOrUpy9aNl/18ujIhJZ2/JMUYlzH0TOBc1YCKIuZLNPwYfxZW6JmosfKXjAFUK7eDn4tU6LSXyo2GNLYzjY71OyCOpllJYtxg/NDAQBlmMCbFPpFCCTjPECU0sGnhfPAdlsyYngT3L0bSyjAZpPRfYrfPd4i3j2niPq9BwF/iOIR95T2CK7zqxXB4TIpporSE0pItmFgynGTh+IwtZm9iAY6pgENShKQaHxJvNj1O5ddYeCwW3H2SqjrHroeOt82xGkH5stZ7g28Uy7iPIPEehlkrB7ry/KjLq9DAo4zVneHhfKJBUBTBxz944AZhd0d9VvSRGgEXnmxzTsHma9hnkwQfGdbXwH4ja582o7hPEI98AAgoo5OCuV/vyMHHgrJBa7z+7eRtGnCeg+EJZy9WlsilHHGze4QGDEDc4NJypNZM4JON503hXON', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ASIAUEESB34CT3URIQHE/20210808/eu-west-1/elasticmapreduce/aws4_request, SignedHeaders=content-type;host;x-amz-date;x-amz-security-token;x-amz-target, Signature=66e13f874221cb3c1b275a052ac56a7e827d431e940bfe9b14414104e0a3b162', 'Content-Length': '59'}&gt;
[2021-08-08 05:29:38,702] {httpsession.py:50} DEBUG - Certificate path: /home/airflow/.local/lib/python3.6/site-packages/certifi/cacert.pem
[2021-08-08 05:29:38,702] {connectionpool.py:943} DEBUG - Starting new HTTPS connection (1): eu-west-1.elasticmapreduce.amazonaws.com:443
[2021-08-08 05:29:38,752] {connectionpool.py:442} DEBUG - https://eu-west-1.elasticmapreduce.amazonaws.com:443 &quot;POST / HTTP/1.1&quot; 200 799
[2021-08-08 05:29:38,752] {parsers.py:233} DEBUG - Response headers: {'x-amzn-RequestId': 'ecacd9e3-44b2-4a00-a4f0-48efe0d65847', 'Content-Type': 'application/x-amz-json-1.1', 'Content-Length': '799', 'Date': 'Sun, 08 Aug 2021 05:29:38 GMT'}
[2021-08-08 05:29:38,752] {parsers.py:234} DEBUG - Response body:
b'{&quot;Step&quot;:{&quot;ActionOnFailure&quot;:&quot;CONTINUE&quot;,&quot;Config&quot;:{&quot;Args&quot;:[&quot;spark-submit&quot;,&quot;--deploy-mode&quot;,&quot;cluster&quot;,&quot;--master&quot;,&quot;yarn&quot;,&quot;--driver-memory&quot;,&quot;2G&quot;,&quot;--executor-memory&quot;,&quot;8G&quot;,&quot;--num-executors&quot;,&quot;5&quot;,&quot;--executor-cores&quot;,&quot;3&quot;,&quot;--packages&quot;,&quot;io.delta:delta-core_2.11:0.6.1&quot;,&quot;--py-files&quot;,&quot;s3://vrt-datalake-artifacts-prod/adobe-target-catalog-sporza/python/adobe_target_catalog_sporza-1.0.0-py3.7_6.egg,s3://vrt-datalake-artifacts-prod/python-datalake-helpers/vrt_datalake_helpers-21-py3-none-any.whl&quot;,&quot;s3://vrt-datalake-artifacts-prod/adobe-target-catalog-sporza/python/run_6.py&quot;,&quot;prod&quot;,&quot;2021-08-08 05:28:00&quot;],&quot;Jar&quot;:&quot;command-runner.jar&quot;,&quot;Properties&quot;:{}},&quot;Id&quot;:&quot;s-581MKMYKRED7&quot;,&quot;Name&quot;:&quot;adobe-target-catalog-sporza-job&quot;,&quot;Status&quot;:{&quot;State&quot;:&quot;PENDING&quot;,&quot;StateChangeReason&quot;:{},&quot;Timeline&quot;:{&quot;CreationDateTime&quot;:1.628400523922E9}}}}'
[2021-08-08 05:29:38,753] {hooks.py:210} DEBUG - Event needs-retry.emr.DescribeStep: calling handler &lt;botocore.retryhandler.RetryHandler object at 0x7fc8dba19860&gt;
[2021-08-08 05:29:38,753] {retryhandler.py:187} DEBUG - No retry needed.
[2021-08-08 05:29:38,753] {emr_base.py:66} INFO - Job flow currently PENDING
[2021-08-08 05:29:38,753] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:29:39,718] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:29:39,748] {taskinstance.py:1906} DEBUG - Task Duration set to 17.617928
[2021-08-08 05:29:42,695] {taskinstance.py:1484} INFO - Rescheduling task, marking task as UP_FOR_RESCHEDULE
[2021-08-08 05:29:42,696] {cli_action_loggers.py:84} DEBUG - Calling callbacks: []
[2021-08-08 05:29:44,944] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:29:48,268] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]&gt;
[2021-08-08 05:29:48,674] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:29:48,674] {local_task_job.py:149} INFO - Task exited with return code 0
[2021-08-08 05:29:48,675] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]&gt; from DB
[2021-08-08 05:29:49,740] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]&gt;
[2021-08-08 05:30:49,437] {__init__.py:51} DEBUG - Loading core task runner: StandardTaskRunner
[2021-08-08 05:30:51,569] {base_task_runner.py:62} DEBUG - Planning to run as the  user
[2021-08-08 05:30:51,572] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; from DB
[2021-08-08 05:30:52,465] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:30:52,465] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:30:52,465] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Instance State' PASSED: True, Task state queued was valid.
[2021-08-08 05:30:52,544] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:30:52,544] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:30:52,545] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Instance Not Running' PASSED: True, Task is not in running state.
[2021-08-08 05:30:52,546] {taskinstance.py:896} INFO - Dependencies all met for &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:30:52,546] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:30:52,593] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:30:52,593] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:30:52,756] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Pool Slots Available' PASSED: True, ('There are enough open slots in %s to execute the task', 'default_pool')
[2021-08-08 05:30:52,756] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Concurrency' PASSED: True, Task concurrency is not set.
[2021-08-08 05:30:52,756] {taskinstance.py:896} INFO - Dependencies all met for &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:30:52,756] {taskinstance.py:1087} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:30:52,756] {taskinstance.py:1088} INFO - Starting attempt 1 of 1
[2021-08-08 05:30:52,756] {taskinstance.py:1089} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:30:53,648] {taskinstance.py:1107} INFO - Executing &lt;Task(EmrStepSensor): watch_adobe_target_catalog_sporza_job_emr_step&gt; on 2021-08-07T05:28:00+00:00
[2021-08-08 05:30:53,651] {standard_task_runner.py:52} INFO - Started process 7972 to run task
[2021-08-08 05:30:53,655] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', 'derived.adobe_target_catalog_sporza', 'watch_adobe_target_catalog_sporza_job_emr_step', '2021-08-07T05:28:00+00:00', '--job-id', '98953', '--pool', 'default_pool', '--raw', '--subdir', 'DAGS_FOLDER/adobe_target_catalog_sporza_wf.py', '--cfg-path', '/tmp/tmppdcqbh0o', '--error-file', '/tmp/tmpdky_uy36']
[2021-08-08 05:30:53,655] {standard_task_runner.py:77} INFO - Job 98953: Subtask watch_adobe_target_catalog_sporza_job_emr_step
[2021-08-08 05:30:53,656] {cli_action_loggers.py:66} DEBUG - Calling callbacks: [&lt;function default_action_log at 0x7fc8dfbe5d90&gt;]
[2021-08-08 05:30:54,515] {settings.py:208} DEBUG - Setting up DB connection pool (PID 7972)
[2021-08-08 05:30:54,515] {settings.py:244} DEBUG - settings.prepare_engine_args(): Using NullPool
[2021-08-08 05:30:54,517] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [None]&gt; from DB
[2021-08-08 05:30:57,090] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:30:58,979] {logging_mixin.py:104} INFO - Running &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; on host ip-172-31-58-121.eu-west-1.compute.internal
[2021-08-08 05:30:58,979] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:30:59,588] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:31:03,931] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:31:04,181] {taskinstance.py:677} DEBUG - Clearing XCom data
[2021-08-08 05:31:04,914] {taskinstance.py:684} DEBUG - XCom data cleared
[2021-08-08 05:31:05,896] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:31:05,934] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:31:12,815] {taskinstance.py:1302} INFO - Exporting the following env vars:
AIRFLOW_CTX_DAG_OWNER=vrt
AIRFLOW_CTX_DAG_ID=derived.adobe_target_catalog_sporza
AIRFLOW_CTX_TASK_ID=watch_adobe_target_catalog_sporza_job_emr_step
AIRFLOW_CTX_EXECUTION_DATE=2021-08-07T05:28:00+00:00
AIRFLOW_CTX_DAG_RUN_ID=scheduled__2021-08-07T05:28:00+00:00
[2021-08-08 05:31:12,815] {__init__.py:146} DEBUG - Preparing lineage inlets and outlets
[2021-08-08 05:31:12,816] {__init__.py:190} DEBUG - inlets: [], outlets: []
[2021-08-08 05:31:13,431] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:31:13,718] {base_aws.py:368} INFO - Airflow Connection: aws_conn_id=aws_default
[2021-08-08 05:31:14,251] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:31:14,293] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:31:14,780] {base_aws.py:179} INFO - No credentials retrieved from Connection
[2021-08-08 05:31:14,780] {base_aws.py:87} INFO - Creating session with aws_access_key_id=None region_name=None
[2021-08-08 05:31:14,781] {hooks.py:417} DEBUG - Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
[2021-08-08 05:31:14,783] {hooks.py:417} DEBUG - Changing event name from before-call.apigateway to before-call.api-gateway
[2021-08-08 05:31:14,784] {hooks.py:417} DEBUG - Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
[2021-08-08 05:31:14,786] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
[2021-08-08 05:31:14,786] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.route53 to before-parameter-build.route-53
[2021-08-08 05:31:14,786] {hooks.py:417} DEBUG - Changing event name from request-created.cloudsearchdomain.Search to request-created.cloudsearch-domain.Search
[2021-08-08 05:31:14,787] {hooks.py:417} DEBUG - Changing event name from docs.*.autoscaling.CreateLaunchConfiguration.complete-section to docs.*.auto-scaling.CreateLaunchConfiguration.complete-section
[2021-08-08 05:31:14,790] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.logs.CreateExportTask to before-parameter-build.cloudwatch-logs.CreateExportTask
[2021-08-08 05:31:14,790] {hooks.py:417} DEBUG - Changing event name from docs.*.logs.CreateExportTask.complete-section to docs.*.cloudwatch-logs.CreateExportTask.complete-section
[2021-08-08 05:31:14,790] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.cloudsearchdomain.Search to before-parameter-build.cloudsearch-domain.Search
[2021-08-08 05:31:14,790] {hooks.py:417} DEBUG - Changing event name from docs.*.cloudsearchdomain.Search.complete-section to docs.*.cloudsearch-domain.Search.complete-section
[2021-08-08 05:31:14,791] {base_aws.py:157} INFO - role_arn is None
[2021-08-08 05:31:14,794] {utils.py:364} DEBUG - IMDS ENDPOINT: http://169.254.169.254/
[2021-08-08 05:31:14,796] {credentials.py:1974} DEBUG - Looking for credentials via: env
[2021-08-08 05:31:14,796] {credentials.py:1974} DEBUG - Looking for credentials via: assume-role
[2021-08-08 05:31:14,796] {credentials.py:1974} DEBUG - Looking for credentials via: assume-role-with-web-identity
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: sso
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: shared-credentials-file
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: custom-process
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: config-file
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: ec2-credentials-file
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: boto-config
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: container-role
[2021-08-08 05:31:14,798] {connectionpool.py:230} DEBUG - Starting new HTTP connection (1): 169.254.170.2:80
[2021-08-08 05:31:14,799] {connectionpool.py:442} DEBUG - http://169.254.170.2:80 &quot;GET /v2/credentials/c5f7099a-d46e-4472-a48f-6c137db9e75d HTTP/1.1&quot; 200 1307
[2021-08-08 05:31:14,800] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/endpoints.json
[2021-08-08 05:31:14,810] {hooks.py:210} DEBUG - Event choose-service-name: calling handler &lt;function handle_service_name_alias at 0x7fc8dbee9bf8&gt;
[2021-08-08 05:31:14,817] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/emr/2009-03-31/service-2.json
[2021-08-08 05:31:14,822] {hooks.py:210} DEBUG - Event creating-client-class.emr: calling handler &lt;function add_generate_presigned_url at 0x7fc8dbf957b8&gt;
[2021-08-08 05:31:14,824] {endpoint.py:292} DEBUG - Setting elasticmapreduce timeout as (60, 60)
[2021-08-08 05:31:14,825] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/_retry.json
[2021-08-08 05:31:14,825] {client.py:166} DEBUG - Registering retry handlers for service: emr
[2021-08-08 05:31:14,826] {emr_step.py:73} INFO - Poking step s-581MKMYKRED7 on cluster j-XDTNJDHR23RQ
[2021-08-08 05:31:14,826] {hooks.py:210} DEBUG - Event before-parameter-build.emr.DescribeStep: calling handler &lt;function generate_idempotent_uuid at 0x7fc8dbf07048&gt;
[2021-08-08 05:31:14,826] {hooks.py:210} DEBUG - Event before-call.emr.DescribeStep: calling handler &lt;function inject_api_version_header_if_needed at 0x7fc8dbf087b8&gt;
[2021-08-08 05:31:14,826] {endpoint.py:101} DEBUG - Making request for OperationModel(name=DescribeStep) with params: {'url_path': '/', 'query_string': '', 'method': 'POST', 'headers': {'X-Amz-Target': 'ElasticMapReduce.DescribeStep', 'Content-Type': 'application/x-amz-json-1.1', 'User-Agent': 'Boto3/1.17.107 Python/3.6.13 Linux/4.14.238-182.422.amzn2.x86_64 exec-env/AWS_ECS_FARGATE Botocore/1.20.107'}, 'body': b'{&quot;ClusterId&quot;: &quot;j-XDTNJDHR23RQ&quot;, &quot;StepId&quot;: &quot;s-581MKMYKRED7&quot;}', 'url': 'https://eu-west-1.elasticmapreduce.amazonaws.com/', 'context': {'client_region': 'eu-west-1', 'client_config': &lt;botocore.config.Config object at 0x7fc8dba0feb8&gt;, 'has_streaming_input': False, 'auth_type': None}}
[2021-08-08 05:31:14,826] {hooks.py:210} DEBUG - Event request-created.emr.DescribeStep: calling handler &lt;bound method RequestSigner.handler of &lt;botocore.signers.RequestSigner object at 0x7fc8dba0fe80&gt;&gt;
[2021-08-08 05:31:14,827] {hooks.py:210} DEBUG - Event choose-signer.emr.DescribeStep: calling handler &lt;function set_operation_specific_signer at 0x7fc8dbf01ea0&gt;
[2021-08-08 05:31:14,827] {auth.py:380} DEBUG - Calculating signature using v4 auth.
[2021-08-08 05:31:14,827] {auth.py:381} DEBUG - CanonicalRequest:
POST
/

content-type:application/x-amz-json-1.1
host:eu-west-1.elasticmapreduce.amazonaws.com
x-amz-date:20210808T053114Z
x-amz-security-token:IQoJb3JpZ2luX2VjEGwaCWV1LXdlc3QtMSJHMEUCIQCZ4NXI3+3YJKZwyu+L4vTyY4swRSd7+zHkDO3Nwc0JiwIgdDuzR2+qJ5vFE03B1RRhzZYGV4Iy/pt7jVXRr0YjXTUqogQIhP//////////ARABGgwyODM3NzQxNDgzNTciDDl+9YdFHetmruZnfSr2A4vFCZwFNe0LEigdz0ayjIhvTZMsjY6CClml27JRBbUllyWz6t3b5SjafRWERgfEe1xIjnFFvp/UFSDIrZVuOefX94uUcgWQKV5zhz/dHdpCzpPltF+syapd2IeY5lgaUZWr+ax+Pfs75JILyfTpa7u43hg1M6P9L07zP/IUWdrXvyvu0wVh07r6/bHUDKJGy52Ok2q6Hr4ltT4MVAY/EZIEDZA8dlNdd7/UDddecp+/7/QIMftzZsgQJVyO+IIB+cfHCIV+1g/ACnsSbBkJuH2fn/B0YeP6e1135yTFknzNKVUxf6OeBIuPrkcu78HnaOXcjv+JSKb9AcFP+2zOo9JYmr040XGVqesZiAc+uDWbL74LDQ7ze5b4sLSNXfCCEvqsYVy9Nt7UlopCXoIS2lBrWgXNhsppDQ976Gr+WgyV1Wbjx2NZlJFCtSNarwF0qDPBmm6yhQxyKMYarOrUpy9aNl/18ujIhJZ2/JMUYlzH0TOBc1YCKIuZLNPwYfxZW6JmosfKXjAFUK7eDn4tU6LSXyo2GNLYzjY71OyCOpllJYtxg/NDAQBlmMCbFPpFCCTjPECU0sGnhfPAdlsyYngT3L0bSyjAZpPRfYrfPd4i3j2niPq9BwF/iOIR95T2CK7zqxXB4TIpporSE0pItmFgynGTh+IwtZm9iAY6pgENShKQaHxJvNj1O5ddYeCwW3H2SqjrHroeOt82xGkH5stZ7g28Uy7iPIPEehlkrB7ry/KjLq9DAo4zVneHhfKJBUBTBxz944AZhd0d9VvSRGgEXnmxzTsHma9hnkwQfGdbXwH4ja582o7hPEI98AAgoo5OCuV/vyMHHgrJBa7z+7eRtGnCeg+EJZy9WlsilHHGze4QGDEDc4NJypNZM4JON503hXON
x-amz-target:ElasticMapReduce.DescribeStep

content-type;host;x-amz-date;x-amz-security-token;x-amz-target
2a131454435119560c6fa09b6b1eeeb557aba91e61af62fe4883ccc24890c4f3
[2021-08-08 05:31:14,827] {auth.py:383} DEBUG - StringToSign:
AWS4-HMAC-SHA256
20210808T053114Z
20210808/eu-west-1/elasticmapreduce/aws4_request
a2f4ed4536a8bb05d35fc345f45eec9b42f7e071c230286854f034ea4878ced2
[2021-08-08 05:31:14,827] {auth.py:385} DEBUG - Signature:
90da79c86917ea04d8aed50abba5b1b3d5152e5327941eda3bf485e6af620e6b
[2021-08-08 05:31:14,827] {endpoint.py:187} DEBUG - Sending http request: &lt;AWSPreparedRequest stream_output=False, method=POST, url=https://eu-west-1.elasticmapreduce.amazonaws.com/, headers={'X-Amz-Target': b'ElasticMapReduce.DescribeStep', 'Content-Type': b'application/x-amz-json-1.1', 'User-Agent': b'Boto3/1.17.107 Python/3.6.13 Linux/4.14.238-182.422.amzn2.x86_64 exec-env/AWS_ECS_FARGATE Botocore/1.20.107', 'X-Amz-Date': b'20210808T053114Z', 'X-Amz-Security-Token': b'IQoJb3JpZ2luX2VjEGwaCWV1LXdlc3QtMSJHMEUCIQCZ4NXI3+3YJKZwyu+L4vTyY4swRSd7+zHkDO3Nwc0JiwIgdDuzR2+qJ5vFE03B1RRhzZYGV4Iy/pt7jVXRr0YjXTUqogQIhP//////////ARABGgwyODM3NzQxNDgzNTciDDl+9YdFHetmruZnfSr2A4vFCZwFNe0LEigdz0ayjIhvTZMsjY6CClml27JRBbUllyWz6t3b5SjafRWERgfEe1xIjnFFvp/UFSDIrZVuOefX94uUcgWQKV5zhz/dHdpCzpPltF+syapd2IeY5lgaUZWr+ax+Pfs75JILyfTpa7u43hg1M6P9L07zP/IUWdrXvyvu0wVh07r6/bHUDKJGy52Ok2q6Hr4ltT4MVAY/EZIEDZA8dlNdd7/UDddecp+/7/QIMftzZsgQJVyO+IIB+cfHCIV+1g/ACnsSbBkJuH2fn/B0YeP6e1135yTFknzNKVUxf6OeBIuPrkcu78HnaOXcjv+JSKb9AcFP+2zOo9JYmr040XGVqesZiAc+uDWbL74LDQ7ze5b4sLSNXfCCEvqsYVy9Nt7UlopCXoIS2lBrWgXNhsppDQ976Gr+WgyV1Wbjx2NZlJFCtSNarwF0qDPBmm6yhQxyKMYarOrUpy9aNl/18ujIhJZ2/JMUYlzH0TOBc1YCKIuZLNPwYfxZW6JmosfKXjAFUK7eDn4tU6LSXyo2GNLYzjY71OyCOpllJYtxg/NDAQBlmMCbFPpFCCTjPECU0sGnhfPAdlsyYngT3L0bSyjAZpPRfYrfPd4i3j2niPq9BwF/iOIR95T2CK7zqxXB4TIpporSE0pItmFgynGTh+IwtZm9iAY6pgENShKQaHxJvNj1O5ddYeCwW3H2SqjrHroeOt82xGkH5stZ7g28Uy7iPIPEehlkrB7ry/KjLq9DAo4zVneHhfKJBUBTBxz944AZhd0d9VvSRGgEXnmxzTsHma9hnkwQfGdbXwH4ja582o7hPEI98AAgoo5OCuV/vyMHHgrJBa7z+7eRtGnCeg+EJZy9WlsilHHGze4QGDEDc4NJypNZM4JON503hXON', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ASIAUEESB34CT3URIQHE/20210808/eu-west-1/elasticmapreduce/aws4_request, SignedHeaders=content-type;host;x-amz-date;x-amz-security-token;x-amz-target, Signature=90da79c86917ea04d8aed50abba5b1b3d5152e5327941eda3bf485e6af620e6b', 'Content-Length': '59'}&gt;
[2021-08-08 05:31:14,828] {httpsession.py:50} DEBUG - Certificate path: /home/airflow/.local/lib/python3.6/site-packages/certifi/cacert.pem
[2021-08-08 05:31:14,828] {connectionpool.py:943} DEBUG - Starting new HTTPS connection (1): eu-west-1.elasticmapreduce.amazonaws.com:443
[2021-08-08 05:31:15,021] {connectionpool.py:442} DEBUG - https://eu-west-1.elasticmapreduce.amazonaws.com:443 &quot;POST / HTTP/1.1&quot; 200 799
[2021-08-08 05:31:15,021] {parsers.py:233} DEBUG - Response headers: {'x-amzn-RequestId': '12e9220a-4dc3-4ca0-9ec9-93a529032f9b', 'Content-Type': 'application/x-amz-json-1.1', 'Content-Length': '799', 'Date': 'Sun, 08 Aug 2021 05:31:14 GMT'}
[2021-08-08 05:31:15,021] {parsers.py:234} DEBUG - Response body:
b'{&quot;Step&quot;:{&quot;ActionOnFailure&quot;:&quot;CONTINUE&quot;,&quot;Config&quot;:{&quot;Args&quot;:[&quot;spark-submit&quot;,&quot;--deploy-mode&quot;,&quot;cluster&quot;,&quot;--master&quot;,&quot;yarn&quot;,&quot;--driver-memory&quot;,&quot;2G&quot;,&quot;--executor-memory&quot;,&quot;8G&quot;,&quot;--num-executors&quot;,&quot;5&quot;,&quot;--executor-cores&quot;,&quot;3&quot;,&quot;--packages&quot;,&quot;io.delta:delta-core_2.11:0.6.1&quot;,&quot;--py-files&quot;,&quot;s3://vrt-datalake-artifacts-prod/adobe-target-catalog-sporza/python/adobe_target_catalog_sporza-1.0.0-py3.7_6.egg,s3://vrt-datalake-artifacts-prod/python-datalake-helpers/vrt_datalake_helpers-21-py3-none-any.whl&quot;,&quot;s3://vrt-datalake-artifacts-prod/adobe-target-catalog-sporza/python/run_6.py&quot;,&quot;prod&quot;,&quot;2021-08-08 05:28:00&quot;],&quot;Jar&quot;:&quot;command-runner.jar&quot;,&quot;Properties&quot;:{}},&quot;Id&quot;:&quot;s-581MKMYKRED7&quot;,&quot;Name&quot;:&quot;adobe-target-catalog-sporza-job&quot;,&quot;Status&quot;:{&quot;State&quot;:&quot;PENDING&quot;,&quot;StateChangeReason&quot;:{},&quot;Timeline&quot;:{&quot;CreationDateTime&quot;:1.628400523922E9}}}}'
[2021-08-08 05:31:15,022] {hooks.py:210} DEBUG - Event needs-retry.emr.DescribeStep: calling handler &lt;botocore.retryhandler.RetryHandler object at 0x7fc8db9b82e8&gt;
[2021-08-08 05:31:15,022] {retryhandler.py:187} DEBUG - No retry needed.
[2021-08-08 05:31:15,023] {emr_base.py:66} INFO - Job flow currently PENDING
[2021-08-08 05:31:15,023] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:31:17,730] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:31:17,771] {taskinstance.py:1906} DEBUG - Task Duration set to 25.225634
[2021-08-08 05:31:21,580] {taskinstance.py:1484} INFO - Rescheduling task, marking task as UP_FOR_RESCHEDULE
[2021-08-08 05:31:21,581] {cli_action_loggers.py:84} DEBUG - Calling callbacks: []
[2021-08-08 05:31:24,405] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:31:26,452] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]&gt;
[2021-08-08 05:31:26,531] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:31:26,531] {local_task_job.py:149} INFO - Task exited with return code 0
[2021-08-08 05:31:26,531] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]&gt; from DB
[2021-08-08 05:31:27,269] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]&gt;
[2021-08-08 05:32:35,215] {__init__.py:51} DEBUG - Loading core task runner: StandardTaskRunner
[2021-08-08 05:32:36,815] {base_task_runner.py:62} DEBUG - Planning to run as the  user
[2021-08-08 05:32:36,817] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; from DB
[2021-08-08 05:32:38,537] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:32:38,537] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:32:38,538] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Instance State' PASSED: True, Task state queued was valid.
[2021-08-08 05:32:38,578] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:32:38,578] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:32:38,579] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Instance Not Running' PASSED: True, Task is not in running state.
[2021-08-08 05:32:38,579] {taskinstance.py:896} INFO - Dependencies all met for &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:32:38,579] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:32:39,309] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:32:39,310] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:32:39,477] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Pool Slots Available' PASSED: True, ('There are enough open slots in %s to execute the task', 'default_pool')
[2021-08-08 05:32:39,477] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Concurrency' PASSED: True, Task concurrency is not set.
[2021-08-08 05:32:39,477] {taskinstance.py:896} INFO - Dependencies all met for &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:32:39,477] {taskinstance.py:1087} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:32:39,477] {taskinstance.py:1088} INFO - Starting attempt 1 of 1
[2021-08-08 05:32:39,477] {taskinstance.py:1089} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:32:43,976] {taskinstance.py:1107} INFO - Executing &lt;Task(EmrStepSensor): watch_adobe_target_catalog_sporza_job_emr_step&gt; on 2021-08-07T05:28:00+00:00
[2021-08-08 05:32:43,979] {standard_task_runner.py:52} INFO - Started process 8339 to run task
[2021-08-08 05:32:43,984] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', 'derived.adobe_target_catalog_sporza', 'watch_adobe_target_catalog_sporza_job_emr_step', '2021-08-07T05:28:00+00:00', '--job-id', '98962', '--pool', 'default_pool', '--raw', '--subdir', 'DAGS_FOLDER/adobe_target_catalog_sporza_wf.py', '--cfg-path', '/tmp/tmpbqux_rdl', '--error-file', '/tmp/tmpyb9gdojg']
[2021-08-08 05:32:43,984] {standard_task_runner.py:77} INFO - Job 98962: Subtask watch_adobe_target_catalog_sporza_job_emr_step
[2021-08-08 05:32:43,985] {cli_action_loggers.py:66} DEBUG - Calling callbacks: [&lt;function default_action_log at 0x7fc8dfbe5d90&gt;]
[2021-08-08 05:32:51,719] {settings.py:208} DEBUG - Setting up DB connection pool (PID 8339)
[2021-08-08 05:32:51,720] {settings.py:244} DEBUG - settings.prepare_engine_args(): Using NullPool
[2021-08-08 05:32:51,722] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [None]&gt; from DB
[2021-08-08 05:32:53,315] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:32:54,868] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:32:55,812] {logging_mixin.py:104} INFO - Running &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; on host ip-172-31-58-121.eu-west-1.compute.internal
[2021-08-08 05:32:55,813] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:32:57,199] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:32:57,203] {local_task_job.py:194} WARNING - Recorded pid 7972 does not match the current pid 8339
[2021-08-08 05:32:57,206] {process_utils.py:100} INFO - Sending Signals.SIGTERM to GPID 8339
[2021-08-08 05:32:57,210] {process_utils.py:66} INFO - Process psutil.Process(pid=8339, status='terminated', exitcode=&lt;Negsignal.SIGTERM: -15&gt;, started='05:32:43') (8339) terminated with exit code Negsignal.SIGTERM"><pre class="notranslate"><code class="notranslate">*** Reading local file: /opt/airflow/logs/derived.adobe_target_catalog_sporza/watch_adobe_target_catalog_sporza_job_emr_step/2021-08-07T05:28:00+00:00/1.log
[2021-08-08 05:29:20,367] {__init__.py:51} DEBUG - Loading core task runner: StandardTaskRunner
[2021-08-08 05:29:21,594] {base_task_runner.py:62} DEBUG - Planning to run as the  user
[2021-08-08 05:29:21,597] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; from DB
[2021-08-08 05:29:22,086] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:29:22,086] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:29:22,086] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Instance State' PASSED: True, Task state queued was valid.
[2021-08-08 05:29:22,128] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:29:22,128] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:29:22,129] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Instance Not Running' PASSED: True, Task is not in running state.
[2021-08-08 05:29:22,130] {taskinstance.py:896} INFO - Dependencies all met for &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:29:22,130] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:29:22,165] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:29:22,206] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:29:22,327] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Pool Slots Available' PASSED: True, ('There are enough open slots in %s to execute the task', 'default_pool')
[2021-08-08 05:29:22,327] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Concurrency' PASSED: True, Task concurrency is not set.
[2021-08-08 05:29:22,327] {taskinstance.py:896} INFO - Dependencies all met for &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:29:22,327] {taskinstance.py:1087} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:29:22,327] {taskinstance.py:1088} INFO - Starting attempt 1 of 1
[2021-08-08 05:29:22,327] {taskinstance.py:1089} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:29:24,417] {taskinstance.py:1107} INFO - Executing &lt;Task(EmrStepSensor): watch_adobe_target_catalog_sporza_job_emr_step&gt; on 2021-08-07T05:28:00+00:00
[2021-08-08 05:29:24,421] {standard_task_runner.py:52} INFO - Started process 7426 to run task
[2021-08-08 05:29:24,427] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', 'derived.adobe_target_catalog_sporza', 'watch_adobe_target_catalog_sporza_job_emr_step', '2021-08-07T05:28:00+00:00', '--job-id', '98940', '--pool', 'default_pool', '--raw', '--subdir', 'DAGS_FOLDER/adobe_target_catalog_sporza_wf.py', '--cfg-path', '/tmp/tmpucsqr5ep', '--error-file', '/tmp/tmpi1wh32jz']
[2021-08-08 05:29:24,427] {standard_task_runner.py:77} INFO - Job 98940: Subtask watch_adobe_target_catalog_sporza_job_emr_step
[2021-08-08 05:29:24,428] {cli_action_loggers.py:66} DEBUG - Calling callbacks: [&lt;function default_action_log at 0x7fc8dfbe5d90&gt;]
[2021-08-08 05:29:26,223] {settings.py:208} DEBUG - Setting up DB connection pool (PID 7426)
[2021-08-08 05:29:26,223] {settings.py:244} DEBUG - settings.prepare_engine_args(): Using NullPool
[2021-08-08 05:29:26,226] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [None]&gt; from DB
[2021-08-08 05:29:27,030] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:29:27,523] {logging_mixin.py:104} INFO - Running &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; on host ip-172-31-58-121.eu-west-1.compute.internal
[2021-08-08 05:29:27,523] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:29:28,218] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:29:28,871] {taskinstance.py:677} DEBUG - Clearing XCom data
[2021-08-08 05:29:29,515] {taskinstance.py:684} DEBUG - XCom data cleared
[2021-08-08 05:29:32,916] {taskinstance.py:1302} INFO - Exporting the following env vars:
AIRFLOW_CTX_DAG_OWNER=vrt
AIRFLOW_CTX_DAG_ID=derived.adobe_target_catalog_sporza
AIRFLOW_CTX_TASK_ID=watch_adobe_target_catalog_sporza_job_emr_step
AIRFLOW_CTX_EXECUTION_DATE=2021-08-07T05:28:00+00:00
AIRFLOW_CTX_DAG_RUN_ID=scheduled__2021-08-07T05:28:00+00:00
[2021-08-08 05:29:32,916] {__init__.py:146} DEBUG - Preparing lineage inlets and outlets
[2021-08-08 05:29:32,916] {__init__.py:190} DEBUG - inlets: [], outlets: []
[2021-08-08 05:29:33,486] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:29:36,437] {base_aws.py:368} INFO - Airflow Connection: aws_conn_id=aws_default
[2021-08-08 05:29:36,521] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:29:36,562] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:29:38,654] {base_aws.py:179} INFO - No credentials retrieved from Connection
[2021-08-08 05:29:38,654] {base_aws.py:87} INFO - Creating session with aws_access_key_id=None region_name=None
[2021-08-08 05:29:38,655] {hooks.py:417} DEBUG - Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
[2021-08-08 05:29:38,656] {hooks.py:417} DEBUG - Changing event name from before-call.apigateway to before-call.api-gateway
[2021-08-08 05:29:38,657] {hooks.py:417} DEBUG - Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
[2021-08-08 05:29:38,659] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
[2021-08-08 05:29:38,659] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.route53 to before-parameter-build.route-53
[2021-08-08 05:29:38,659] {hooks.py:417} DEBUG - Changing event name from request-created.cloudsearchdomain.Search to request-created.cloudsearch-domain.Search
[2021-08-08 05:29:38,660] {hooks.py:417} DEBUG - Changing event name from docs.*.autoscaling.CreateLaunchConfiguration.complete-section to docs.*.auto-scaling.CreateLaunchConfiguration.complete-section
[2021-08-08 05:29:38,663] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.logs.CreateExportTask to before-parameter-build.cloudwatch-logs.CreateExportTask
[2021-08-08 05:29:38,663] {hooks.py:417} DEBUG - Changing event name from docs.*.logs.CreateExportTask.complete-section to docs.*.cloudwatch-logs.CreateExportTask.complete-section
[2021-08-08 05:29:38,663] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.cloudsearchdomain.Search to before-parameter-build.cloudsearch-domain.Search
[2021-08-08 05:29:38,663] {hooks.py:417} DEBUG - Changing event name from docs.*.cloudsearchdomain.Search.complete-section to docs.*.cloudsearch-domain.Search.complete-section
[2021-08-08 05:29:38,664] {base_aws.py:157} INFO - role_arn is None
[2021-08-08 05:29:38,667] {utils.py:364} DEBUG - IMDS ENDPOINT: http://169.254.169.254/
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: env
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: assume-role
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: assume-role-with-web-identity
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: sso
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: shared-credentials-file
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: custom-process
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: config-file
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: ec2-credentials-file
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: boto-config
[2021-08-08 05:29:38,670] {credentials.py:1974} DEBUG - Looking for credentials via: container-role
[2021-08-08 05:29:38,671] {connectionpool.py:230} DEBUG - Starting new HTTP connection (1): 169.254.170.2:80
[2021-08-08 05:29:38,673] {connectionpool.py:442} DEBUG - http://169.254.170.2:80 "GET /v2/credentials/c5f7099a-d46e-4472-a48f-6c137db9e75d HTTP/1.1" 200 1307
[2021-08-08 05:29:38,674] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/endpoints.json
[2021-08-08 05:29:38,683] {hooks.py:210} DEBUG - Event choose-service-name: calling handler &lt;function handle_service_name_alias at 0x7fc8dbee8bf8&gt;
[2021-08-08 05:29:38,691] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/emr/2009-03-31/service-2.json
[2021-08-08 05:29:38,695] {hooks.py:210} DEBUG - Event creating-client-class.emr: calling handler &lt;function add_generate_presigned_url at 0x7fc8dbf947b8&gt;
[2021-08-08 05:29:38,697] {endpoint.py:292} DEBUG - Setting elasticmapreduce timeout as (60, 60)
[2021-08-08 05:29:38,698] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/_retry.json
[2021-08-08 05:29:38,698] {client.py:166} DEBUG - Registering retry handlers for service: emr
[2021-08-08 05:29:38,699] {emr_step.py:73} INFO - Poking step s-581MKMYKRED7 on cluster j-XDTNJDHR23RQ
[2021-08-08 05:29:38,699] {hooks.py:210} DEBUG - Event before-parameter-build.emr.DescribeStep: calling handler &lt;function generate_idempotent_uuid at 0x7fc8dbf06048&gt;
[2021-08-08 05:29:38,699] {hooks.py:210} DEBUG - Event before-call.emr.DescribeStep: calling handler &lt;function inject_api_version_header_if_needed at 0x7fc8dbf077b8&gt;
[2021-08-08 05:29:38,699] {endpoint.py:101} DEBUG - Making request for OperationModel(name=DescribeStep) with params: {'url_path': '/', 'query_string': '', 'method': 'POST', 'headers': {'X-Amz-Target': 'ElasticMapReduce.DescribeStep', 'Content-Type': 'application/x-amz-json-1.1', 'User-Agent': 'Boto3/1.17.107 Python/3.6.13 Linux/4.14.238-182.422.amzn2.x86_64 exec-env/AWS_ECS_FARGATE Botocore/1.20.107'}, 'body': b'{"ClusterId": "j-XDTNJDHR23RQ", "StepId": "s-581MKMYKRED7"}', 'url': 'https://eu-west-1.elasticmapreduce.amazonaws.com/', 'context': {'client_region': 'eu-west-1', 'client_config': &lt;botocore.config.Config object at 0x7fc8dba19470&gt;, 'has_streaming_input': False, 'auth_type': None}}
[2021-08-08 05:29:38,700] {hooks.py:210} DEBUG - Event request-created.emr.DescribeStep: calling handler &lt;bound method RequestSigner.handler of &lt;botocore.signers.RequestSigner object at 0x7fc8dba19438&gt;&gt;
[2021-08-08 05:29:38,700] {hooks.py:210} DEBUG - Event choose-signer.emr.DescribeStep: calling handler &lt;function set_operation_specific_signer at 0x7fc8dbf01ea0&gt;
[2021-08-08 05:29:38,700] {auth.py:380} DEBUG - Calculating signature using v4 auth.
[2021-08-08 05:29:38,700] {auth.py:381} DEBUG - CanonicalRequest:
POST
/

content-type:application/x-amz-json-1.1
host:eu-west-1.elasticmapreduce.amazonaws.com
x-amz-date:20210808T052938Z
x-amz-security-token:IQoJb3JpZ2luX2VjEGwaCWV1LXdlc3QtMSJHMEUCIQCZ4NXI3+3YJKZwyu+L4vTyY4swRSd7+zHkDO3Nwc0JiwIgdDuzR2+qJ5vFE03B1RRhzZYGV4Iy/pt7jVXRr0YjXTUqogQIhP//////////ARABGgwyODM3NzQxNDgzNTciDDl+9YdFHetmruZnfSr2A4vFCZwFNe0LEigdz0ayjIhvTZMsjY6CClml27JRBbUllyWz6t3b5SjafRWERgfEe1xIjnFFvp/UFSDIrZVuOefX94uUcgWQKV5zhz/dHdpCzpPltF+syapd2IeY5lgaUZWr+ax+Pfs75JILyfTpa7u43hg1M6P9L07zP/IUWdrXvyvu0wVh07r6/bHUDKJGy52Ok2q6Hr4ltT4MVAY/EZIEDZA8dlNdd7/UDddecp+/7/QIMftzZsgQJVyO+IIB+cfHCIV+1g/ACnsSbBkJuH2fn/B0YeP6e1135yTFknzNKVUxf6OeBIuPrkcu78HnaOXcjv+JSKb9AcFP+2zOo9JYmr040XGVqesZiAc+uDWbL74LDQ7ze5b4sLSNXfCCEvqsYVy9Nt7UlopCXoIS2lBrWgXNhsppDQ976Gr+WgyV1Wbjx2NZlJFCtSNarwF0qDPBmm6yhQxyKMYarOrUpy9aNl/18ujIhJZ2/JMUYlzH0TOBc1YCKIuZLNPwYfxZW6JmosfKXjAFUK7eDn4tU6LSXyo2GNLYzjY71OyCOpllJYtxg/NDAQBlmMCbFPpFCCTjPECU0sGnhfPAdlsyYngT3L0bSyjAZpPRfYrfPd4i3j2niPq9BwF/iOIR95T2CK7zqxXB4TIpporSE0pItmFgynGTh+IwtZm9iAY6pgENShKQaHxJvNj1O5ddYeCwW3H2SqjrHroeOt82xGkH5stZ7g28Uy7iPIPEehlkrB7ry/KjLq9DAo4zVneHhfKJBUBTBxz944AZhd0d9VvSRGgEXnmxzTsHma9hnkwQfGdbXwH4ja582o7hPEI98AAgoo5OCuV/vyMHHgrJBa7z+7eRtGnCeg+EJZy9WlsilHHGze4QGDEDc4NJypNZM4JON503hXON
x-amz-target:ElasticMapReduce.DescribeStep

content-type;host;x-amz-date;x-amz-security-token;x-amz-target
2a131454435119560c6fa09b6b1eeeb557aba91e61af62fe4883ccc24890c4f3
[2021-08-08 05:29:38,700] {auth.py:383} DEBUG - StringToSign:
AWS4-HMAC-SHA256
20210808T052938Z
20210808/eu-west-1/elasticmapreduce/aws4_request
29f0d229d76daf02f334b8c7d193cb06de4619f4adb7b3057683f53b2ea79c80
[2021-08-08 05:29:38,700] {auth.py:385} DEBUG - Signature:
66e13f874221cb3c1b275a052ac56a7e827d431e940bfe9b14414104e0a3b162
[2021-08-08 05:29:38,701] {endpoint.py:187} DEBUG - Sending http request: &lt;AWSPreparedRequest stream_output=False, method=POST, url=https://eu-west-1.elasticmapreduce.amazonaws.com/, headers={'X-Amz-Target': b'ElasticMapReduce.DescribeStep', 'Content-Type': b'application/x-amz-json-1.1', 'User-Agent': b'Boto3/1.17.107 Python/3.6.13 Linux/4.14.238-182.422.amzn2.x86_64 exec-env/AWS_ECS_FARGATE Botocore/1.20.107', 'X-Amz-Date': b'20210808T052938Z', 'X-Amz-Security-Token': b'IQoJb3JpZ2luX2VjEGwaCWV1LXdlc3QtMSJHMEUCIQCZ4NXI3+3YJKZwyu+L4vTyY4swRSd7+zHkDO3Nwc0JiwIgdDuzR2+qJ5vFE03B1RRhzZYGV4Iy/pt7jVXRr0YjXTUqogQIhP//////////ARABGgwyODM3NzQxNDgzNTciDDl+9YdFHetmruZnfSr2A4vFCZwFNe0LEigdz0ayjIhvTZMsjY6CClml27JRBbUllyWz6t3b5SjafRWERgfEe1xIjnFFvp/UFSDIrZVuOefX94uUcgWQKV5zhz/dHdpCzpPltF+syapd2IeY5lgaUZWr+ax+Pfs75JILyfTpa7u43hg1M6P9L07zP/IUWdrXvyvu0wVh07r6/bHUDKJGy52Ok2q6Hr4ltT4MVAY/EZIEDZA8dlNdd7/UDddecp+/7/QIMftzZsgQJVyO+IIB+cfHCIV+1g/ACnsSbBkJuH2fn/B0YeP6e1135yTFknzNKVUxf6OeBIuPrkcu78HnaOXcjv+JSKb9AcFP+2zOo9JYmr040XGVqesZiAc+uDWbL74LDQ7ze5b4sLSNXfCCEvqsYVy9Nt7UlopCXoIS2lBrWgXNhsppDQ976Gr+WgyV1Wbjx2NZlJFCtSNarwF0qDPBmm6yhQxyKMYarOrUpy9aNl/18ujIhJZ2/JMUYlzH0TOBc1YCKIuZLNPwYfxZW6JmosfKXjAFUK7eDn4tU6LSXyo2GNLYzjY71OyCOpllJYtxg/NDAQBlmMCbFPpFCCTjPECU0sGnhfPAdlsyYngT3L0bSyjAZpPRfYrfPd4i3j2niPq9BwF/iOIR95T2CK7zqxXB4TIpporSE0pItmFgynGTh+IwtZm9iAY6pgENShKQaHxJvNj1O5ddYeCwW3H2SqjrHroeOt82xGkH5stZ7g28Uy7iPIPEehlkrB7ry/KjLq9DAo4zVneHhfKJBUBTBxz944AZhd0d9VvSRGgEXnmxzTsHma9hnkwQfGdbXwH4ja582o7hPEI98AAgoo5OCuV/vyMHHgrJBa7z+7eRtGnCeg+EJZy9WlsilHHGze4QGDEDc4NJypNZM4JON503hXON', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ASIAUEESB34CT3URIQHE/20210808/eu-west-1/elasticmapreduce/aws4_request, SignedHeaders=content-type;host;x-amz-date;x-amz-security-token;x-amz-target, Signature=66e13f874221cb3c1b275a052ac56a7e827d431e940bfe9b14414104e0a3b162', 'Content-Length': '59'}&gt;
[2021-08-08 05:29:38,702] {httpsession.py:50} DEBUG - Certificate path: /home/airflow/.local/lib/python3.6/site-packages/certifi/cacert.pem
[2021-08-08 05:29:38,702] {connectionpool.py:943} DEBUG - Starting new HTTPS connection (1): eu-west-1.elasticmapreduce.amazonaws.com:443
[2021-08-08 05:29:38,752] {connectionpool.py:442} DEBUG - https://eu-west-1.elasticmapreduce.amazonaws.com:443 "POST / HTTP/1.1" 200 799
[2021-08-08 05:29:38,752] {parsers.py:233} DEBUG - Response headers: {'x-amzn-RequestId': 'ecacd9e3-44b2-4a00-a4f0-48efe0d65847', 'Content-Type': 'application/x-amz-json-1.1', 'Content-Length': '799', 'Date': 'Sun, 08 Aug 2021 05:29:38 GMT'}
[2021-08-08 05:29:38,752] {parsers.py:234} DEBUG - Response body:
b'{"Step":{"ActionOnFailure":"CONTINUE","Config":{"Args":["spark-submit","--deploy-mode","cluster","--master","yarn","--driver-memory","2G","--executor-memory","8G","--num-executors","5","--executor-cores","3","--packages","io.delta:delta-core_2.11:0.6.1","--py-files","s3://vrt-datalake-artifacts-prod/adobe-target-catalog-sporza/python/adobe_target_catalog_sporza-1.0.0-py3.7_6.egg,s3://vrt-datalake-artifacts-prod/python-datalake-helpers/vrt_datalake_helpers-21-py3-none-any.whl","s3://vrt-datalake-artifacts-prod/adobe-target-catalog-sporza/python/run_6.py","prod","2021-08-08 05:28:00"],"Jar":"command-runner.jar","Properties":{}},"Id":"s-581MKMYKRED7","Name":"adobe-target-catalog-sporza-job","Status":{"State":"PENDING","StateChangeReason":{},"Timeline":{"CreationDateTime":1.628400523922E9}}}}'
[2021-08-08 05:29:38,753] {hooks.py:210} DEBUG - Event needs-retry.emr.DescribeStep: calling handler &lt;botocore.retryhandler.RetryHandler object at 0x7fc8dba19860&gt;
[2021-08-08 05:29:38,753] {retryhandler.py:187} DEBUG - No retry needed.
[2021-08-08 05:29:38,753] {emr_base.py:66} INFO - Job flow currently PENDING
[2021-08-08 05:29:38,753] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:29:39,718] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:29:39,748] {taskinstance.py:1906} DEBUG - Task Duration set to 17.617928
[2021-08-08 05:29:42,695] {taskinstance.py:1484} INFO - Rescheduling task, marking task as UP_FOR_RESCHEDULE
[2021-08-08 05:29:42,696] {cli_action_loggers.py:84} DEBUG - Calling callbacks: []
[2021-08-08 05:29:44,944] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:29:48,268] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]&gt;
[2021-08-08 05:29:48,674] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:29:48,674] {local_task_job.py:149} INFO - Task exited with return code 0
[2021-08-08 05:29:48,675] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]&gt; from DB
[2021-08-08 05:29:49,740] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]&gt;
[2021-08-08 05:30:49,437] {__init__.py:51} DEBUG - Loading core task runner: StandardTaskRunner
[2021-08-08 05:30:51,569] {base_task_runner.py:62} DEBUG - Planning to run as the  user
[2021-08-08 05:30:51,572] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; from DB
[2021-08-08 05:30:52,465] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:30:52,465] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:30:52,465] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Instance State' PASSED: True, Task state queued was valid.
[2021-08-08 05:30:52,544] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:30:52,544] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:30:52,545] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Instance Not Running' PASSED: True, Task is not in running state.
[2021-08-08 05:30:52,546] {taskinstance.py:896} INFO - Dependencies all met for &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:30:52,546] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:30:52,593] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:30:52,593] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:30:52,756] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Pool Slots Available' PASSED: True, ('There are enough open slots in %s to execute the task', 'default_pool')
[2021-08-08 05:30:52,756] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Concurrency' PASSED: True, Task concurrency is not set.
[2021-08-08 05:30:52,756] {taskinstance.py:896} INFO - Dependencies all met for &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:30:52,756] {taskinstance.py:1087} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:30:52,756] {taskinstance.py:1088} INFO - Starting attempt 1 of 1
[2021-08-08 05:30:52,756] {taskinstance.py:1089} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:30:53,648] {taskinstance.py:1107} INFO - Executing &lt;Task(EmrStepSensor): watch_adobe_target_catalog_sporza_job_emr_step&gt; on 2021-08-07T05:28:00+00:00
[2021-08-08 05:30:53,651] {standard_task_runner.py:52} INFO - Started process 7972 to run task
[2021-08-08 05:30:53,655] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', 'derived.adobe_target_catalog_sporza', 'watch_adobe_target_catalog_sporza_job_emr_step', '2021-08-07T05:28:00+00:00', '--job-id', '98953', '--pool', 'default_pool', '--raw', '--subdir', 'DAGS_FOLDER/adobe_target_catalog_sporza_wf.py', '--cfg-path', '/tmp/tmppdcqbh0o', '--error-file', '/tmp/tmpdky_uy36']
[2021-08-08 05:30:53,655] {standard_task_runner.py:77} INFO - Job 98953: Subtask watch_adobe_target_catalog_sporza_job_emr_step
[2021-08-08 05:30:53,656] {cli_action_loggers.py:66} DEBUG - Calling callbacks: [&lt;function default_action_log at 0x7fc8dfbe5d90&gt;]
[2021-08-08 05:30:54,515] {settings.py:208} DEBUG - Setting up DB connection pool (PID 7972)
[2021-08-08 05:30:54,515] {settings.py:244} DEBUG - settings.prepare_engine_args(): Using NullPool
[2021-08-08 05:30:54,517] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [None]&gt; from DB
[2021-08-08 05:30:57,090] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:30:58,979] {logging_mixin.py:104} INFO - Running &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; on host ip-172-31-58-121.eu-west-1.compute.internal
[2021-08-08 05:30:58,979] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:30:59,588] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:31:03,931] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:31:04,181] {taskinstance.py:677} DEBUG - Clearing XCom data
[2021-08-08 05:31:04,914] {taskinstance.py:684} DEBUG - XCom data cleared
[2021-08-08 05:31:05,896] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:31:05,934] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:31:12,815] {taskinstance.py:1302} INFO - Exporting the following env vars:
AIRFLOW_CTX_DAG_OWNER=vrt
AIRFLOW_CTX_DAG_ID=derived.adobe_target_catalog_sporza
AIRFLOW_CTX_TASK_ID=watch_adobe_target_catalog_sporza_job_emr_step
AIRFLOW_CTX_EXECUTION_DATE=2021-08-07T05:28:00+00:00
AIRFLOW_CTX_DAG_RUN_ID=scheduled__2021-08-07T05:28:00+00:00
[2021-08-08 05:31:12,815] {__init__.py:146} DEBUG - Preparing lineage inlets and outlets
[2021-08-08 05:31:12,816] {__init__.py:190} DEBUG - inlets: [], outlets: []
[2021-08-08 05:31:13,431] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:31:13,718] {base_aws.py:368} INFO - Airflow Connection: aws_conn_id=aws_default
[2021-08-08 05:31:14,251] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:31:14,293] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:31:14,780] {base_aws.py:179} INFO - No credentials retrieved from Connection
[2021-08-08 05:31:14,780] {base_aws.py:87} INFO - Creating session with aws_access_key_id=None region_name=None
[2021-08-08 05:31:14,781] {hooks.py:417} DEBUG - Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
[2021-08-08 05:31:14,783] {hooks.py:417} DEBUG - Changing event name from before-call.apigateway to before-call.api-gateway
[2021-08-08 05:31:14,784] {hooks.py:417} DEBUG - Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
[2021-08-08 05:31:14,786] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
[2021-08-08 05:31:14,786] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.route53 to before-parameter-build.route-53
[2021-08-08 05:31:14,786] {hooks.py:417} DEBUG - Changing event name from request-created.cloudsearchdomain.Search to request-created.cloudsearch-domain.Search
[2021-08-08 05:31:14,787] {hooks.py:417} DEBUG - Changing event name from docs.*.autoscaling.CreateLaunchConfiguration.complete-section to docs.*.auto-scaling.CreateLaunchConfiguration.complete-section
[2021-08-08 05:31:14,790] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.logs.CreateExportTask to before-parameter-build.cloudwatch-logs.CreateExportTask
[2021-08-08 05:31:14,790] {hooks.py:417} DEBUG - Changing event name from docs.*.logs.CreateExportTask.complete-section to docs.*.cloudwatch-logs.CreateExportTask.complete-section
[2021-08-08 05:31:14,790] {hooks.py:417} DEBUG - Changing event name from before-parameter-build.cloudsearchdomain.Search to before-parameter-build.cloudsearch-domain.Search
[2021-08-08 05:31:14,790] {hooks.py:417} DEBUG - Changing event name from docs.*.cloudsearchdomain.Search.complete-section to docs.*.cloudsearch-domain.Search.complete-section
[2021-08-08 05:31:14,791] {base_aws.py:157} INFO - role_arn is None
[2021-08-08 05:31:14,794] {utils.py:364} DEBUG - IMDS ENDPOINT: http://169.254.169.254/
[2021-08-08 05:31:14,796] {credentials.py:1974} DEBUG - Looking for credentials via: env
[2021-08-08 05:31:14,796] {credentials.py:1974} DEBUG - Looking for credentials via: assume-role
[2021-08-08 05:31:14,796] {credentials.py:1974} DEBUG - Looking for credentials via: assume-role-with-web-identity
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: sso
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: shared-credentials-file
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: custom-process
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: config-file
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: ec2-credentials-file
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: boto-config
[2021-08-08 05:31:14,797] {credentials.py:1974} DEBUG - Looking for credentials via: container-role
[2021-08-08 05:31:14,798] {connectionpool.py:230} DEBUG - Starting new HTTP connection (1): 169.254.170.2:80
[2021-08-08 05:31:14,799] {connectionpool.py:442} DEBUG - http://169.254.170.2:80 "GET /v2/credentials/c5f7099a-d46e-4472-a48f-6c137db9e75d HTTP/1.1" 200 1307
[2021-08-08 05:31:14,800] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/endpoints.json
[2021-08-08 05:31:14,810] {hooks.py:210} DEBUG - Event choose-service-name: calling handler &lt;function handle_service_name_alias at 0x7fc8dbee9bf8&gt;
[2021-08-08 05:31:14,817] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/emr/2009-03-31/service-2.json
[2021-08-08 05:31:14,822] {hooks.py:210} DEBUG - Event creating-client-class.emr: calling handler &lt;function add_generate_presigned_url at 0x7fc8dbf957b8&gt;
[2021-08-08 05:31:14,824] {endpoint.py:292} DEBUG - Setting elasticmapreduce timeout as (60, 60)
[2021-08-08 05:31:14,825] {loaders.py:174} DEBUG - Loading JSON file: /home/airflow/.local/lib/python3.6/site-packages/botocore/data/_retry.json
[2021-08-08 05:31:14,825] {client.py:166} DEBUG - Registering retry handlers for service: emr
[2021-08-08 05:31:14,826] {emr_step.py:73} INFO - Poking step s-581MKMYKRED7 on cluster j-XDTNJDHR23RQ
[2021-08-08 05:31:14,826] {hooks.py:210} DEBUG - Event before-parameter-build.emr.DescribeStep: calling handler &lt;function generate_idempotent_uuid at 0x7fc8dbf07048&gt;
[2021-08-08 05:31:14,826] {hooks.py:210} DEBUG - Event before-call.emr.DescribeStep: calling handler &lt;function inject_api_version_header_if_needed at 0x7fc8dbf087b8&gt;
[2021-08-08 05:31:14,826] {endpoint.py:101} DEBUG - Making request for OperationModel(name=DescribeStep) with params: {'url_path': '/', 'query_string': '', 'method': 'POST', 'headers': {'X-Amz-Target': 'ElasticMapReduce.DescribeStep', 'Content-Type': 'application/x-amz-json-1.1', 'User-Agent': 'Boto3/1.17.107 Python/3.6.13 Linux/4.14.238-182.422.amzn2.x86_64 exec-env/AWS_ECS_FARGATE Botocore/1.20.107'}, 'body': b'{"ClusterId": "j-XDTNJDHR23RQ", "StepId": "s-581MKMYKRED7"}', 'url': 'https://eu-west-1.elasticmapreduce.amazonaws.com/', 'context': {'client_region': 'eu-west-1', 'client_config': &lt;botocore.config.Config object at 0x7fc8dba0feb8&gt;, 'has_streaming_input': False, 'auth_type': None}}
[2021-08-08 05:31:14,826] {hooks.py:210} DEBUG - Event request-created.emr.DescribeStep: calling handler &lt;bound method RequestSigner.handler of &lt;botocore.signers.RequestSigner object at 0x7fc8dba0fe80&gt;&gt;
[2021-08-08 05:31:14,827] {hooks.py:210} DEBUG - Event choose-signer.emr.DescribeStep: calling handler &lt;function set_operation_specific_signer at 0x7fc8dbf01ea0&gt;
[2021-08-08 05:31:14,827] {auth.py:380} DEBUG - Calculating signature using v4 auth.
[2021-08-08 05:31:14,827] {auth.py:381} DEBUG - CanonicalRequest:
POST
/

content-type:application/x-amz-json-1.1
host:eu-west-1.elasticmapreduce.amazonaws.com
x-amz-date:20210808T053114Z
x-amz-security-token:IQoJb3JpZ2luX2VjEGwaCWV1LXdlc3QtMSJHMEUCIQCZ4NXI3+3YJKZwyu+L4vTyY4swRSd7+zHkDO3Nwc0JiwIgdDuzR2+qJ5vFE03B1RRhzZYGV4Iy/pt7jVXRr0YjXTUqogQIhP//////////ARABGgwyODM3NzQxNDgzNTciDDl+9YdFHetmruZnfSr2A4vFCZwFNe0LEigdz0ayjIhvTZMsjY6CClml27JRBbUllyWz6t3b5SjafRWERgfEe1xIjnFFvp/UFSDIrZVuOefX94uUcgWQKV5zhz/dHdpCzpPltF+syapd2IeY5lgaUZWr+ax+Pfs75JILyfTpa7u43hg1M6P9L07zP/IUWdrXvyvu0wVh07r6/bHUDKJGy52Ok2q6Hr4ltT4MVAY/EZIEDZA8dlNdd7/UDddecp+/7/QIMftzZsgQJVyO+IIB+cfHCIV+1g/ACnsSbBkJuH2fn/B0YeP6e1135yTFknzNKVUxf6OeBIuPrkcu78HnaOXcjv+JSKb9AcFP+2zOo9JYmr040XGVqesZiAc+uDWbL74LDQ7ze5b4sLSNXfCCEvqsYVy9Nt7UlopCXoIS2lBrWgXNhsppDQ976Gr+WgyV1Wbjx2NZlJFCtSNarwF0qDPBmm6yhQxyKMYarOrUpy9aNl/18ujIhJZ2/JMUYlzH0TOBc1YCKIuZLNPwYfxZW6JmosfKXjAFUK7eDn4tU6LSXyo2GNLYzjY71OyCOpllJYtxg/NDAQBlmMCbFPpFCCTjPECU0sGnhfPAdlsyYngT3L0bSyjAZpPRfYrfPd4i3j2niPq9BwF/iOIR95T2CK7zqxXB4TIpporSE0pItmFgynGTh+IwtZm9iAY6pgENShKQaHxJvNj1O5ddYeCwW3H2SqjrHroeOt82xGkH5stZ7g28Uy7iPIPEehlkrB7ry/KjLq9DAo4zVneHhfKJBUBTBxz944AZhd0d9VvSRGgEXnmxzTsHma9hnkwQfGdbXwH4ja582o7hPEI98AAgoo5OCuV/vyMHHgrJBa7z+7eRtGnCeg+EJZy9WlsilHHGze4QGDEDc4NJypNZM4JON503hXON
x-amz-target:ElasticMapReduce.DescribeStep

content-type;host;x-amz-date;x-amz-security-token;x-amz-target
2a131454435119560c6fa09b6b1eeeb557aba91e61af62fe4883ccc24890c4f3
[2021-08-08 05:31:14,827] {auth.py:383} DEBUG - StringToSign:
AWS4-HMAC-SHA256
20210808T053114Z
20210808/eu-west-1/elasticmapreduce/aws4_request
a2f4ed4536a8bb05d35fc345f45eec9b42f7e071c230286854f034ea4878ced2
[2021-08-08 05:31:14,827] {auth.py:385} DEBUG - Signature:
90da79c86917ea04d8aed50abba5b1b3d5152e5327941eda3bf485e6af620e6b
[2021-08-08 05:31:14,827] {endpoint.py:187} DEBUG - Sending http request: &lt;AWSPreparedRequest stream_output=False, method=POST, url=https://eu-west-1.elasticmapreduce.amazonaws.com/, headers={'X-Amz-Target': b'ElasticMapReduce.DescribeStep', 'Content-Type': b'application/x-amz-json-1.1', 'User-Agent': b'Boto3/1.17.107 Python/3.6.13 Linux/4.14.238-182.422.amzn2.x86_64 exec-env/AWS_ECS_FARGATE Botocore/1.20.107', 'X-Amz-Date': b'20210808T053114Z', 'X-Amz-Security-Token': b'IQoJb3JpZ2luX2VjEGwaCWV1LXdlc3QtMSJHMEUCIQCZ4NXI3+3YJKZwyu+L4vTyY4swRSd7+zHkDO3Nwc0JiwIgdDuzR2+qJ5vFE03B1RRhzZYGV4Iy/pt7jVXRr0YjXTUqogQIhP//////////ARABGgwyODM3NzQxNDgzNTciDDl+9YdFHetmruZnfSr2A4vFCZwFNe0LEigdz0ayjIhvTZMsjY6CClml27JRBbUllyWz6t3b5SjafRWERgfEe1xIjnFFvp/UFSDIrZVuOefX94uUcgWQKV5zhz/dHdpCzpPltF+syapd2IeY5lgaUZWr+ax+Pfs75JILyfTpa7u43hg1M6P9L07zP/IUWdrXvyvu0wVh07r6/bHUDKJGy52Ok2q6Hr4ltT4MVAY/EZIEDZA8dlNdd7/UDddecp+/7/QIMftzZsgQJVyO+IIB+cfHCIV+1g/ACnsSbBkJuH2fn/B0YeP6e1135yTFknzNKVUxf6OeBIuPrkcu78HnaOXcjv+JSKb9AcFP+2zOo9JYmr040XGVqesZiAc+uDWbL74LDQ7ze5b4sLSNXfCCEvqsYVy9Nt7UlopCXoIS2lBrWgXNhsppDQ976Gr+WgyV1Wbjx2NZlJFCtSNarwF0qDPBmm6yhQxyKMYarOrUpy9aNl/18ujIhJZ2/JMUYlzH0TOBc1YCKIuZLNPwYfxZW6JmosfKXjAFUK7eDn4tU6LSXyo2GNLYzjY71OyCOpllJYtxg/NDAQBlmMCbFPpFCCTjPECU0sGnhfPAdlsyYngT3L0bSyjAZpPRfYrfPd4i3j2niPq9BwF/iOIR95T2CK7zqxXB4TIpporSE0pItmFgynGTh+IwtZm9iAY6pgENShKQaHxJvNj1O5ddYeCwW3H2SqjrHroeOt82xGkH5stZ7g28Uy7iPIPEehlkrB7ry/KjLq9DAo4zVneHhfKJBUBTBxz944AZhd0d9VvSRGgEXnmxzTsHma9hnkwQfGdbXwH4ja582o7hPEI98AAgoo5OCuV/vyMHHgrJBa7z+7eRtGnCeg+EJZy9WlsilHHGze4QGDEDc4NJypNZM4JON503hXON', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ASIAUEESB34CT3URIQHE/20210808/eu-west-1/elasticmapreduce/aws4_request, SignedHeaders=content-type;host;x-amz-date;x-amz-security-token;x-amz-target, Signature=90da79c86917ea04d8aed50abba5b1b3d5152e5327941eda3bf485e6af620e6b', 'Content-Length': '59'}&gt;
[2021-08-08 05:31:14,828] {httpsession.py:50} DEBUG - Certificate path: /home/airflow/.local/lib/python3.6/site-packages/certifi/cacert.pem
[2021-08-08 05:31:14,828] {connectionpool.py:943} DEBUG - Starting new HTTPS connection (1): eu-west-1.elasticmapreduce.amazonaws.com:443
[2021-08-08 05:31:15,021] {connectionpool.py:442} DEBUG - https://eu-west-1.elasticmapreduce.amazonaws.com:443 "POST / HTTP/1.1" 200 799
[2021-08-08 05:31:15,021] {parsers.py:233} DEBUG - Response headers: {'x-amzn-RequestId': '12e9220a-4dc3-4ca0-9ec9-93a529032f9b', 'Content-Type': 'application/x-amz-json-1.1', 'Content-Length': '799', 'Date': 'Sun, 08 Aug 2021 05:31:14 GMT'}
[2021-08-08 05:31:15,021] {parsers.py:234} DEBUG - Response body:
b'{"Step":{"ActionOnFailure":"CONTINUE","Config":{"Args":["spark-submit","--deploy-mode","cluster","--master","yarn","--driver-memory","2G","--executor-memory","8G","--num-executors","5","--executor-cores","3","--packages","io.delta:delta-core_2.11:0.6.1","--py-files","s3://vrt-datalake-artifacts-prod/adobe-target-catalog-sporza/python/adobe_target_catalog_sporza-1.0.0-py3.7_6.egg,s3://vrt-datalake-artifacts-prod/python-datalake-helpers/vrt_datalake_helpers-21-py3-none-any.whl","s3://vrt-datalake-artifacts-prod/adobe-target-catalog-sporza/python/run_6.py","prod","2021-08-08 05:28:00"],"Jar":"command-runner.jar","Properties":{}},"Id":"s-581MKMYKRED7","Name":"adobe-target-catalog-sporza-job","Status":{"State":"PENDING","StateChangeReason":{},"Timeline":{"CreationDateTime":1.628400523922E9}}}}'
[2021-08-08 05:31:15,022] {hooks.py:210} DEBUG - Event needs-retry.emr.DescribeStep: calling handler &lt;botocore.retryhandler.RetryHandler object at 0x7fc8db9b82e8&gt;
[2021-08-08 05:31:15,022] {retryhandler.py:187} DEBUG - No retry needed.
[2021-08-08 05:31:15,023] {emr_base.py:66} INFO - Job flow currently PENDING
[2021-08-08 05:31:15,023] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:31:17,730] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:31:17,771] {taskinstance.py:1906} DEBUG - Task Duration set to 25.225634
[2021-08-08 05:31:21,580] {taskinstance.py:1484} INFO - Rescheduling task, marking task as UP_FOR_RESCHEDULE
[2021-08-08 05:31:21,581] {cli_action_loggers.py:84} DEBUG - Calling callbacks: []
[2021-08-08 05:31:24,405] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:31:26,452] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]&gt;
[2021-08-08 05:31:26,531] {base_job.py:227} DEBUG - [heartbeat]
[2021-08-08 05:31:26,531] {local_task_job.py:149} INFO - Task exited with return code 0
[2021-08-08 05:31:26,531] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]&gt; from DB
[2021-08-08 05:31:27,269] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [up_for_reschedule]&gt;
[2021-08-08 05:32:35,215] {__init__.py:51} DEBUG - Loading core task runner: StandardTaskRunner
[2021-08-08 05:32:36,815] {base_task_runner.py:62} DEBUG - Planning to run as the  user
[2021-08-08 05:32:36,817] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; from DB
[2021-08-08 05:32:38,537] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:32:38,537] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:32:38,538] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Instance State' PASSED: True, Task state queued was valid.
[2021-08-08 05:32:38,578] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:32:38,578] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:32:38,579] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Instance Not Running' PASSED: True, Task is not in running state.
[2021-08-08 05:32:38,579] {taskinstance.py:896} INFO - Dependencies all met for &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:32:38,579] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set.
[2021-08-08 05:32:39,309] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Ready To Reschedule' PASSED: True, The task instance is not in State_UP_FOR_RESCHEDULE or NONE state.
[2021-08-08 05:32:39,310] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
[2021-08-08 05:32:39,477] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Pool Slots Available' PASSED: True, ('There are enough open slots in %s to execute the task', 'default_pool')
[2021-08-08 05:32:39,477] {taskinstance.py:911} DEBUG - &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt; dependency 'Task Concurrency' PASSED: True, Task concurrency is not set.
[2021-08-08 05:32:39,477] {taskinstance.py:896} INFO - Dependencies all met for &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [queued]&gt;
[2021-08-08 05:32:39,477] {taskinstance.py:1087} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:32:39,477] {taskinstance.py:1088} INFO - Starting attempt 1 of 1
[2021-08-08 05:32:39,477] {taskinstance.py:1089} INFO - 
--------------------------------------------------------------------------------
[2021-08-08 05:32:43,976] {taskinstance.py:1107} INFO - Executing &lt;Task(EmrStepSensor): watch_adobe_target_catalog_sporza_job_emr_step&gt; on 2021-08-07T05:28:00+00:00
[2021-08-08 05:32:43,979] {standard_task_runner.py:52} INFO - Started process 8339 to run task
[2021-08-08 05:32:43,984] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', 'derived.adobe_target_catalog_sporza', 'watch_adobe_target_catalog_sporza_job_emr_step', '2021-08-07T05:28:00+00:00', '--job-id', '98962', '--pool', 'default_pool', '--raw', '--subdir', 'DAGS_FOLDER/adobe_target_catalog_sporza_wf.py', '--cfg-path', '/tmp/tmpbqux_rdl', '--error-file', '/tmp/tmpyb9gdojg']
[2021-08-08 05:32:43,984] {standard_task_runner.py:77} INFO - Job 98962: Subtask watch_adobe_target_catalog_sporza_job_emr_step
[2021-08-08 05:32:43,985] {cli_action_loggers.py:66} DEBUG - Calling callbacks: [&lt;function default_action_log at 0x7fc8dfbe5d90&gt;]
[2021-08-08 05:32:51,719] {settings.py:208} DEBUG - Setting up DB connection pool (PID 8339)
[2021-08-08 05:32:51,720] {settings.py:244} DEBUG - settings.prepare_engine_args(): Using NullPool
[2021-08-08 05:32:51,722] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [None]&gt; from DB
[2021-08-08 05:32:53,315] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:32:54,868] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:32:55,812] {logging_mixin.py:104} INFO - Running &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; on host ip-172-31-58-121.eu-west-1.compute.internal
[2021-08-08 05:32:55,813] {taskinstance.py:614} DEBUG - Refreshing TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt; from DB
[2021-08-08 05:32:57,199] {taskinstance.py:649} DEBUG - Refreshed TaskInstance &lt;TaskInstance: derived.adobe_target_catalog_sporza.watch_adobe_target_catalog_sporza_job_emr_step 2021-08-07T05:28:00+00:00 [running]&gt;
[2021-08-08 05:32:57,203] {local_task_job.py:194} WARNING - Recorded pid 7972 does not match the current pid 8339
[2021-08-08 05:32:57,206] {process_utils.py:100} INFO - Sending Signals.SIGTERM to GPID 8339
[2021-08-08 05:32:57,210] {process_utils.py:66} INFO - Process psutil.Process(pid=8339, status='terminated', exitcode=&lt;Negsignal.SIGTERM: -15&gt;, started='05:32:43') (8339) terminated with exit code Negsignal.SIGTERM
</code></pre></div>
</details>
<p dir="auto"><strong>What you expected to happen</strong>:</p>
<p dir="auto">I'd expect the EMRStepSensor to run until the EMR step succeeded, and report a succesful run.</p>
<p dir="auto">If my understanding is correct, these final lines in the log show the runner terminating the task process. If I'm reading the log correctly, 8339 is the correct PID for the task, and the recorded pid 7972 is the pid for a previous run. Could it be possible that this pid is not correctly being updated?</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="[2021-08-08 05:32:57,203] {local_task_job.py:194} WARNING - Recorded pid 7972 does not match the current pid 8339
[2021-08-08 05:32:57,206] {process_utils.py:100} INFO - Sending Signals.SIGTERM to GPID 8339
[2021-08-08 05:32:57,210] {process_utils.py:66} INFO - Process psutil.Process(pid=8339, status='terminated', exitcode=&lt;Negsignal.SIGTERM: -15&gt;, started='05:32:43') (8339) terminated with exit code Negsignal.SIGTERM"><pre class="notranslate"><code class="notranslate">[2021-08-08 05:32:57,203] {local_task_job.py:194} WARNING - Recorded pid 7972 does not match the current pid 8339
[2021-08-08 05:32:57,206] {process_utils.py:100} INFO - Sending Signals.SIGTERM to GPID 8339
[2021-08-08 05:32:57,210] {process_utils.py:66} INFO - Process psutil.Process(pid=8339, status='terminated', exitcode=&lt;Negsignal.SIGTERM: -15&gt;, started='05:32:43') (8339) terminated with exit code Negsignal.SIGTERM
</code></pre></div>
<p dir="auto"><strong>Anything else we need to know</strong>:</p>
<p dir="auto">The symptoms look very similar to <a class="issue-link js-issue-link" data-error-text="Failed to load title" data-id="959156291" data-permission-text="Title is private" data-url="https://github.com/apache/airflow/issues/17394" data-hovercard-type="issue" data-hovercard-url="/apache/airflow/issues/17394/hovercard" href="https://github.com/apache/airflow/issues/17394">#17394</a>, but I'm not using run_as_user, and the reported pids are not the same, so I'm not sure whether this is the same issue.</p>