Failed ndb transaction attempt not rolling back all changes?
<p>I have some trouble understanding a sequence of events causing a bug in my appplication which can only be seen <strong>intermittently</strong> in the app deployed on GAE, and never when running with the local <code>devserver.py</code>.</p>

<p>All the related code snippets below (trimmed for MCV, hopefully I didn't lose anything significant) are executed during handling of <strong>the same</strong> task queue request.</p>

<p>The entry point:</p>

<pre><code>def job_completed_task(self, _):

    # running outside transaction as query is made
    if not self.all_context_jobs_completed(self.context.db_key, self):
        # this will transactionally enqueue another task
        self.trigger_job_mark_completed_transaction()
    else:
        # this is transactional
        self.context.jobs_completed(self)
</code></pre>

<p>The corresponding <code>self.context.jobs_completed(self)</code> is:</p>

<pre><code>@ndb.transactional(xg=True)
def jobs_completed(self, job):

    if self.status == QAStrings.status_done:
        logging.debug('%s jobs_completed %s NOP' % (self.lid, job.job_id))
        return

    # some logic computing step_completed here

    if step_completed:
        self.status = QAStrings.status_done  # includes self.db_data.put()

    # this will transactionally enqueue another task
    job.trigger_job_mark_completed_transaction()
</code></pre>

<p>The <code>self.status</code> setter, hacked to obtain a traceback for debugging this scenario:</p>

<pre><code>@status.setter
def status(self, new_status):
    assert ndb.in_transaction()

    status = getattr(self, self.attr_status)
    if status != new_status:
        traceback.print_stack()
        logging.info('%s status change %s -&gt; %s' % (self.name, status, new_status))
        setattr(self, self.attr_status, new_status)
</code></pre>

<p>The <code>job.trigger_job_mark_completed_transaction()</code> eventually enqueues a new task like this:</p>

<pre><code>    task = taskqueue.add(queue_name=self.task_queue_name, url=url, params=params,
                         transactional=ndb.in_transaction(), countdown=delay)
</code></pre>

<p>The GAE log for the occurence, split as it doesn't fit into a single screen:</p>

<p><a href="http://i.stack.imgur.com/kN5ei.png" rel="nofollow"><img src="http://i.stack.imgur.com/kN5ei.png" alt="enter image description here"></a></p>

<p><a href="http://i.stack.imgur.com/ktDLu.png" rel="nofollow"><img src="http://i.stack.imgur.com/ktDLu.png" alt="enter image description here"></a></p>

<p>My expectation from the <code>jobs_completed</code> transaction is to either see the <code>... jobs_completed ... NOP</code> debug message and no task enqueued or to at least see the <code>status change running -&gt; done</code> info message and a task enqueued by <code>job.trigger_job_mark_completed_transaction()</code>.</p>

<p>What I'm actually seeing is both messages and no task enqueued.</p>

<p>The logs appears to indicate the transaction is attempted twice:</p>

<ul>
<li><p>1st time it finds the status not <code>done</code>, so it executes the logic, sets the status to <code>done</code> (and displays the traceback and the info msg) and should transactionally enqueue the new task - but it doesn't</p></li>
<li><p>2nd time it finds the status <code>done</code> and just prints the debug message</p></li>
</ul>

<p>My question is - if the 1st transaction attempt fails shouldn't the status change be rolled back as well? What am I missing?</p>

<p>I found a workaround: specifying no retries to the <code>jobs_completed()</code> transaction:</p>

<pre><code>@ndb.transactional(xg=True, retries=0)
def jobs_completed(self, job):
</code></pre>

<p>This prevents the automatic repeated execution, instead causing an exception:</p>

<blockquote>
  <p>TransactionFailedError(The transaction could not be committed. Please
  try again.)</p>
</blockquote>

<p>Which is acceptable as I already have in place a back-off/retry safety net for the entire <code>job_completed_task()</code>. Things are OK now.</p>

<p>As for why the rollback didn't happen, the only thing that crosses my mind is that somehow the entity was read (and cached in my object attribute) prior to entering the transaction, thus not being considered part of the (same) transaction. But I couldn't find a code path that would do that, so it's just speculation.</p>

python google-app-engine google-cloud-datastore