# Interleaved stdout bug

**URL:** <https://forum.ansible.com/t/interleaved-stdout-bug/19006>\
**Category:** Ansible Project\
**Created:** [August 12, 2015, 8:00pm UTC](https://forum.ansible.com/t/interleaved-stdout-bug/19006 "2015-08-12T20:00:59Z")\
**Posts on this page:** 2\
**Page:** 1

<div class="post-metadata">

**Author:** ![jmeickle](https://avatars.discourse-cdn.com/v4/letter/j/ccd318/32.png) [@jmeickle](https://forum.ansible.com/u/jmeickle)\
**Post date:** [August 12, 2015, 8:00pm UTC](https://forum.ansible.com/t/interleaved-stdout-bug/19006/1 "2015-08-12T20:00:59Z")

</div>

I use Ansible to coordinate a CI build that takes place across several servers simultaneously. It’s easiest to feed our CI tool stdout, so I was using the “human\_log.py” callback plugin that’s floating around online to add stdout/stderr logging on OK/changed tasks. However, I noticed very strange interleaving of task results in the output:

150812-06:42:34,549 workflow ERROR:  
[‘Node trim\_fslroi failed to run on host YYY.’]  
150812-06:42:34,559 workflow INFO:  
Saving crash info to XXX  
150812-06:42:34,559 workflow INFO:  
Traceback (most recent call last):  
File “XXX/pipeline/plugins/linear.py”, line 38, in run  
node.run(updatehash=updatehash)  
File “XXX/pipeline/engine.py”, line 1386, in run  
self.\_run\_interface()  
File “XXX/pipeline/engine.py”, line 2252, in \_run\_interface  
updatehash=updatehash))  
File "Xfailed: [YYY] =\> (item={“rc”: 1, “start”: “2015-08-12 06:01:52.770879”, “warnings”: , …}

[later in stdout]

Running: ZZZ/a\_different\_command  
150812-06:54:16,889 workflow INFO:  
Executing node a\_different\_command in dir: ZZZ/a\_different\_coXX/pipeline/engine.py", line 2153, in \_collate\_results  
if node.result.outputs:  
AttributeError: ‘NoneType’ object has no attribute ‘outputs’  
…ignoring

I discovered that Ansible internally uses a display() helper function to establish a lock before printing, as opposed to the code sample I used that just naively prints. OK, makes sense - we’re doing an 8+ hour build that contains several 1+ hour tasks producing a LOT of output, so it makes sense that we’d see this race condition more often than everyone else using it.

However, even establishing a lock with the current runner (obtained via stack inspection, since the callback plugin API doesn’t pass it) doesn’t seem to prevent this from happening. I haven’t had time to debug this further, but AFAICT from reading the code base, there’s no support for more advanced control of printing than that.

Any thoughts on how to print sanely in this situation, preferably without having to patch Ansible or log each task to a different file?

---

<div class="post-metadata">

**Author:** ![jmeickle](https://avatars.discourse-cdn.com/v4/letter/j/ccd318/32.png) [@jmeickle](https://forum.ansible.com/u/jmeickle)\
**Post date:** [August 19, 2015, 6:46pm UTC](https://forum.ansible.com/t/interleaved-stdout-bug/19006/2 "2015-08-19T18:46:38Z")

</div>

This is still happening for me with Ansible 1.9.2-1.