Heroku run randomly truncates output

[ejfinneran]

I'm seeing strange behavior with the heroku run command where large output jobs will randomly not return all the data they should.

The concrete use case that surfaced this was using the replicate gem to pull down a lot of relational data for a user.

I recreated it consistently with a basic rails app with a ~3.5MB copy of Shakespeare plays as a text file.

At first I thought it was just truncating the output after it reached a specific byte count but as you can see from the output below, it's seemingly random.

Here's an example of what I'm seeing:

Locally

╰─○ nl shakespeare_plays.txt| tail
 88121  <A NAME=5.4.213>would kiss as many of you as had beards that pleased</A><br>
 88122  <A NAME=5.4.214>me, complexions that liked me and breaths that I</A><br>
 88123  <A NAME=5.4.215>defied not: and, I am sure, as many as have good</A><br>
 88124  <A NAME=5.4.216>beards or good faces or sweet breaths will, for my</A><br>
 88125  <A NAME=5.4.217>kind offer, when I make curtsy, bid me farewell.</A><br>
 88126  <p><i>Exeunt</i></p>
 88127  </body>
 88128  </html>

Via Heroku

$ heroku --version
heroku-toolbelt/2.33.5 (x86_64-darwin10.8.0) ruby/1.9.3


$ heroku run 'cat shakespeare_plays.txt' | nl | tail

 75588  ROMEO   But that a joy past joy calls out on me,
 75589      It were a grief, so brief to part with thee: Farewell.

 75590      [Exeunt]




 75591      ROMEO AND JUL%   

$ heroku run 'cat shakespeare_plays.txt' | nl | tail
 37554  <A NAME=4.4.27>With what it loathes for that which is away.</A><br>
 37555  <A NAME=4.4.28>But more of this hereafter. You, Diana,</A><br>
 37556  <A NAME=4.4.29>Under my poor instructions yet must suffer</A><br>
 37557  <A NAME=4.4.30>Something in my behalf.</A><br>
 37558  </blockquote>

 37559  <A NAME=speech4><b>DIANA</b></a>
 37560  <blockquote>
 37561  <A NAME=4.4.31>Let death and honesty</A><br>
 37562  <A NAME=4.4.32>Go with your impositions, I am yours%

$ heroku run 'cat shakespeare_plays.txt' | nl | tail
 14070  <A NAME=5.2.56>yourself good and not to grace me. Believe then, if</A><br>
 14071  <A NAME=5.2.57>you please, that I can do strange things: I have,</A><br>
 14072  <A NAME=5.2.58>since I was three year old, conversed with a</A><br>
 14073  <A NAME=5.2.59>magician, most profound in his art and yet not</A><br>
 14074  <A NAME=5.2.60>damnable. If you do love Rosalind so near the heart</A><br>
 14075  <A NAME=5.2.61>as your gesture cries it out, when your brother</A><br>
 14076  <A NAME=5.2.62>marries Aliena, shall you marry her: I know into</A><br>
 14077  <A NAME=5.2.63>what straits of fortune she is driven; and it is</A><br>
 14078  <A NAME=5.2.64>not impossible to me, if it appear not inconvenient</A><br>
 14079  <A NAME=5.2.65>to you, to set her before your eyes tomorrow human%   

[wuputah]

Interesting. @mmcgrana, can you speak to the reliability of rendezvous in this manner? Any idea where the bug would be?

[mmcgrana]

@wuputah I'm not immediately sure, sorry. We've definitely had issues of this shape in earlier versions of heroku run. Even the current one isn't really great for Unix pipelines, as examples like this show.

[ianjosephwilson]

Any updates on this? I still seem to be experiencing this. I am still having this issue. What is a good alternative to saving heroku run's output?

[stefansundin]

I'm also experiencing this. I'm also seeing the line

Running `...` attached to terminal... up, run.XXX

on the top. This should in my opinion be printed to stderr instead of stdout, making it more pipe-friendly.

My output file is 51,290 bytes. But since the first line noted above is 90 bytes, the output that was transferred from the server is 51,200 bytes, so this is probably the size of a buffer.

However, every time I run the command, the output is cut off at different points.

What I ended up doing was enabling logging in my terminal (iTerm2), then running heroku run bash, run the command I want the output of, then open the log file and copying the things I needed. In my case the logfile had CRLF line endings, so I had to fix that too. Damn annoying workaround, but it works.

[scottwb]

I am also experiencing this problem with a very simple use case. I run heroku run rake report, which invokes a report rake task that executes a simple database query and dumps around 2000 lines of CSV data very quickly. The output gets cut off in random spots as others have mentioned.

It sure seems like something is closing the connection before all the data is finished being sent. The only workaround I've found so far is to heroku run bash and then rake report from there, and copy/paste the output from the terminal into a CSV file.

[scottwb]

For anyone else that might find this useful...here is the workaround I am using now: add a && sleep 10 to your command, using the same example in my previous comment, here is what I am doing now:

heroku run "rake report && sleep 10" > output.csv

Without the && sleep 10, my output gets cutoff, with the && sleep 10 I have gotten all my output so far.

[funwhilelost]

I'm also seeing this issue. Piping the output into a file results in randomly truncated results.

[jdx]

@infamouse can you give me permission to access your app and try it myself? It'd be good to have a good example test case. If you want you could also email me at jeff@heroku.com.

FYI @heroku/api this isn't likely to be a CLI issue, it's probably rendezvous since this code has been completely ported over to node, but I'll see if I can find out more information.

[Odaeus]

Dunno if this info is useful, but from Heroku support on August 28th 2015:

While we can indeed reproduce this issue, we'll likely need a pretty big change to fix this. Unfortunately, we do not have an ETA for the fix yet, but we're planning to start working on from next week. Thanks for reporting this, with a reproducible way, we really appreciate it.

During the investigation, We tend to see that it goes well with a good network (we were able to reproduce this constantly with slow network), so the only workaround that I can suggest would be using a good network. I'm also seeing a good result if I add something like && sleep 10 at the end (e.g. heroku run 'ruby -e "10000.times {|i| puts i }" && sleep 10', actually not sure how to pass && with --). Other than that, you'll need to make more bigger change to fix this on your end unfortunately (e.g. saving the result and sending to s3, etc.).

[rwz]

Seems like a case of

I'd tell you a UDP joke but I'm not sure you'd get it.

[jdx]

Ah I remember seeing that ticket and I remember we determined it was an issue with the upstream server. I'm going to close this ticket since it is not an issue with the CLI (only the CLI team sees/manages these tickets, and there isn't anything I can do here).

If you're having issues with this, submit a support ticket.