Intermittent argument errors during workspace cleanup

[justindotpub]

When I run mix bootleg.build I pretty regularly (but intermittently) get an error similar to the following during the workspace cleanup step.

** (ArgumentError) argument error
    (stdlib) :io.put_chars(:standard_io, :unicode, [[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[...] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘_build/prod/rel/myapp/lib/db_connection-1.1.2/ebin/db_connection.app’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘_build/prod/rel/myapp/lib/db_connection-1.1.2/ebin/Elixir.DBConnection.Sojourn.Broker.beam’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘_build/prod/rel/myapp/lib/db_connection-1.1.2/ebin/Elixir.DBConnection.App.beam’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘_build/prod/rel/myapp/lib/db_connection-1.1.2/ebin/Elixir.DBConnection.Sojourn.Supervisor.beam’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘_build/prod/rel/myapp/lib/db_connection-1.1.2/ebin/Elixir.DBConnection.Poolboy.Worker.beam’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘_build/prod/rel/myapp/lib/db_connection-1.1.2/ebin/Elixir.DBConnection.Pool.beam’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘_build/prod/rel/myapp/lib/db_connection-1.1.2/ebin/Elixir.DBConnection.Query.beam’"] | "\e[0m"], 10])
    lib/bootleg/ssh.ex:90: Bootleg.SSH.capture/3
    lib/sshkit/ssh/channel.ex:224: SSHKit.SSH.Channel.loop/4
    lib/sshkit/ssh.ex:125: SSHKit.SSH.run/3
    lib/bootleg/ssh.ex:70: anonymous fn/2 in Bootleg.SSH.run/2
    (elixir) lib/enum.ex:1255: Enum."-map/2-lists^map/1-0-"/2
    lib/bootleg/ssh.ex:109: Bootleg.SSH.run!/2
    deps/bootleg/lib/bootleg/tasks/build.exs:31: anonymous fn/3 in Bootleg.DynamicTasks.Clean.execute/0

I haven't taken the time to look into this yet, so forgive me if this is a ticket for sshkit or some other dependency.

[rjanja]

The formatting of sshkit's output is being done by Bootleg, so that does appear to be a bug. Thanks for the feedback!

[justindotpub]

Out of curiosity, is it obvious to you what is causing this bug and have you been able to reproduce it? I ask because I found https://github.com/elixir-lang/elixir/issues/3594 and https://github.com/phoenixframework/phoenix/issues/1051, which are old but point to a (fixed) Erlang bug, and I'm hoping this isn't something unique to Erlang on CentOS 7. I'm using the Erlang package from the Erlang Solutions yum repo and the precompiled Elixir 1.5.1.

Erlang/OTP 20 [erts-9.0] [source] [64-bit] [smp:2:2] [ds:2:2:10] [async-threads:10] [hipe] [kernel-poll:false]

[rjanja]

I haven't been able to reproduce it yet but I'm still trying.

I've pushed up a branch with some output handling changes which I'd be curious to have you try:

{:bootleg, git: "https://github.com/labzero/bootleg", branch: "radams/refactor-color-output", only: :dev, runtime: false},

If you could, try it as-is after issuing a mix deps.get, and if you still hit an error, try adding the following line to your app's config/config.exs:

config :bootleg, output_coloring: false

[justindotpub]

Still broken if I use your branch and if I use your branch with the extra config.

[justindotpub]

More example failures, in case they're helpful.

** (ArgumentError) argument error
    (stdlib) :io.put_chars(:standard_io, :unicode, [[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[...] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘apps/myapp_web/assets/node_modules/true-case-path/index.js’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed directory: ‘apps/myapp_web/assets/node_modules/true-case-path’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘apps/myapp_web/assets/node_modules/mime/.npmignore’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘apps/myapp_web/assets/node_modules/mime/build/test.js’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘apps/myapp_web/assets/node_modules/mime/build/build.js’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed directory: ‘apps/myapp_web/assets/node_modules/mime/build’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘apps/myapp_web/assets/node_modules/mime/README.md’"] | "\e[0m"], 10])
    lib/bootleg/ssh.ex:90: Bootleg.SSH.capture/3
    lib/sshkit/ssh/channel.ex:224: SSHKit.SSH.Channel.loop/4
    lib/sshkit/ssh.ex:125: SSHKit.SSH.run/3
    lib/bootleg/ssh.ex:70: anonymous fn/2 in Bootleg.SSH.run/2
    (elixir) lib/enum.ex:1255: Enum."-map/2-lists^map/1-0-"/2
    lib/bootleg/ssh.ex:109: Bootleg.SSH.run!/2
    deps/bootleg/lib/bootleg/tasks/build.exs:31: anonymous fn/3 in Bootleg.DynamicTasks.Clean.execute/0

 ** (ArgumentError) argument error
    (stdlib) :io.put_chars(:standard_io, :unicode, [[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[...] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘apps/myapp_web/assets/node_modules/core-js/modules/es6.string.strike.js’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘apps/myapp_web/assets/node_modules/core-js/modules/es6.function.has-instance.js’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘apps/myapp_web/assets/node_modules/core-js/modules/es7.string.trim-right.js’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘apps/myapp_web/assets/node_modules/core-js/modules/es6.string.repeat.js’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘apps/myapp_web/assets/node_modules/core-js/modules/_fails.js’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘apps/myapp_web/assets/node_modules/core-js/modules/es6.set.js’"], "\n"] | "\e[0m"] | "\e[1m"] | "\e[34m"], "[MY_IP_ADDRESS ] "] | "\e[0m"], "removed ‘apps/myapp_web/assets/node_modules/core-js/modules/es6.array.every.js’"] | "\e[0m"], 10])
    lib/bootleg/ssh.ex:90: Bootleg.SSH.capture/3
    lib/sshkit/ssh/channel.ex:224: SSHKit.SSH.Channel.loop/4
    lib/sshkit/ssh.ex:125: SSHKit.SSH.run/3
    lib/bootleg/ssh.ex:70: anonymous fn/2 in Bootleg.SSH.run/2
    (elixir) lib/enum.ex:1255: Enum."-map/2-lists^map/1-0-"/2
    lib/bootleg/ssh.ex:109: Bootleg.SSH.run!/2
    deps/bootleg/lib/bootleg/tasks/build.exs:31: anonymous fn/3 in Bootleg.DynamicTasks.Clean.execute/0

[justindotpub]

The above examples are with coloring. Here's one with coloring turned off.

** (ArgumentError) argument error
    (stdlib) :io.put_chars(:standard_io, :unicode, [[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[[...], ...], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/inet_hosts.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/net_kernel.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/standard_error.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/erts_debug.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/disk_log_sup.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/os.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/net.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/user.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/gen_udp.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/inet_res.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/file_io_server.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/application_master.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/gen_tcp.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/rpc.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/inet_db.beam’"], "\n"], "[MY_IP_ADDRESS ] "], "removed ‘_build/prod/rel/myapp/lib/kernel-5.3/ebin/inet6_tcp_dist.beam’"], 10])
    lib/bootleg/ssh.ex:90: Bootleg.SSH.capture/3
    lib/sshkit/ssh/channel.ex:224: SSHKit.SSH.Channel.loop/4
    lib/sshkit/ssh.ex:125: SSHKit.SSH.run/3
    lib/bootleg/ssh.ex:70: anonymous fn/2 in Bootleg.SSH.run/2
    (elixir) lib/enum.ex:1255: Enum."-map/2-lists^map/1-0-"/2
    lib/bootleg/ssh.ex:109: Bootleg.SSH.run!/2
    deps/bootleg/lib/bootleg/tasks/build.exs:31: anonymous fn/3 in Bootleg.DynamicTasks.Clean.execute/0

[rjanja]

That is odd.

Can you try redefining the clean task using the following in your deploy.exs and see if you still get an error?

task :clean do
  IO.puts "not cleaning the workspace"
end

[justindotpub]

It works every time for me so far with that change.

[rjanja]

Thanks for all your help trying to track this down. I'm thinking it's either a character encoding conversion problem as we pipe the data to IO.puts (so, something in one of the filenames that comes over the wire as we do an rm -rvf and rm prints out the files/folders being unlinked), or something related to the amount of data being piped.

[justindotpub]

No problem at all man. Thanks for the project. 😄

The sizes of args passed to :io.put_chars on the failures hasn't been super consistent so I wasn't sure if that ruled out size being the issue. I'll see if I can find anything else that helps narrow this down.

[rjanja]

I think the problem must be a character encoding of one of the file names in your build server's working directory, and I'm guessing that calling a task that prints out all of the same filenames would throw the same error:

task :foo do
  remote :build do
    "ls -alR"
  end
end

$ mix bootleg.invoke foo

[justindotpub]

You are correct. There are a lot of files here so I'll have to spend some time looking through to find the offenders.

Strike that. I was doing it wrong. After defining foo and running mix bootleg.invoke foo all files list just fine. I made sure I had at least one successful build first so all files were still there in the directory.

[rjanja]

Something like the following might help to shorten the list: $ cd /path/to/build/workspace $ LC_ALL=C find . -name '*[! -~]*' | cat (from https://unix.stackexchange.com/questions/109747/identify-files-with-non-ascii-or-non-printable-characters-in-file-name/109753#109753)

[justindotpub]

I updated the task to do rm -rvf * > ../output. The only thing that jumps out at first is the way the quotes look for each line.

removed ‘path/to/file’

[justindotpub]

Since that output is different from rm -rvf on macos...

$ rm --version
rm (GNU coreutils) 8.22
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>.
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

Written by Paul Rubin, David MacKenzie, Richard M. Stallman,
and Jim Meyering.

[justindotpub]

If I make foo do rm -rvf * I get the error again. Sure looks like those quotes to me.

[justindotpub]

Okay, sorry for all the noise on this ticket. I changed the task to cat the previous output of rm and it still failed. Then I removed all but one line and it worked. Then I duplicated that line 16000 times and it failed. So it seems to be related to the size of the file somehow.

[rjanja]

I don't mind the noise at all, thanks for continuing to try to narrow this down. The quotes come over fine for me when executing a ls --quoting-style=locale:

So maybe it's not at all related to characters in the filenames. I'll try reproducing with a long file/more output tonight.

[justindotpub]

Man, I have it narrowed down to a file with just the lines needed to reproduce this. I was hoping it had to do with file size but it doesn't seem to. The file contains a full list of lines (i.e. all of the rm output lines that I kept are complete) and ends with that closing single quote. If I remove the closing single quote it passes. If I replace the single quote with a bunch more chars it works. I was hoping I had found the exact file size to break it. Here's the size of the failing file with the closing single quote.

  Size: 344067      Blocks: 680        IO Block: 4096   regular file

[justindotpub]

The last line of my failing file is as follows.

removed ‘apps/myapp_web/assets/node_modules/fbjs/node_modules/core-js/modules/$.enum-keys.js’

If I remove the last s as follows it still fails.

removed ‘apps/myapp_web/assets/node_modules/fbjs/node_modules/core-js/modules/$.enum-keys.j’

If I add an extra j as follows it works but instead of printing the last line I see the line before it followed by one line with just the ’ on a line by itself and no output of the last line of the file.

last line of file

removed ‘apps/myapp_web/assets/node_modules/fbjs/node_modules/core-js/modules/$.enum-keys.jjs’

last 2 lines of output, first being the second to last line in the file

[MY_IP_ADDRESS ] removed ‘apps/myapp_web/assets/node_modules/fbjs/node_modules/core-js/modules/es6.symbol.js’
[MY_IP_ADDRESS ] ’

[justindotpub]

Okay, a simplified case of weirdness... with a file with just the following 2 lines, if I cat the file in a task I only see the first line.

removed ‘apps/myapp_web/assets/node_modules/fbjs/node_modules/core-js/modules/$.string-pad.js’
removed ‘apps/myapp_web/assets/node_modules/fbjs/node_modules/core-js/modules/$.enum-keys.js’

[rjanja]

Could you attach the failing file or rather part of it?

[justindotpub]

Here it is.

output.txt

[rjanja]

Ok, the last line not displaying appears to be a separate issue. I've just pushed a fix to the refactor-color-output branch.

Nothing pops for me in the file you attached. I can cat it over SSH via Bootleg fine.

I've also been able to cat a file with ten million lines (76 MB) created via $ seq 1 10000000 > dummy.txt and those lines appeared without error via the invoked Bootleg task.

I just took the file you uploaded and repeated those two lines 1,000 times, so 2,000 lines total, and am finally able to reproduce the error you've reported. 🌠

Attaching it here (208 K) repro.txt

[rjanja]

Alright, I think the latest commit bce6da696e319a223e83cd705ee2b9e7a6821a1a to the WIP branch addresses this problem:

• We output data via IO.binwrite instead of IO.puts to avoid the unicode conversion of data
• We set locale in the remote environment when running commands (not necessary, but makes the output nicer to look at)

Thanks again for all your help tracking this down!

Please try this branch again and let me know how it goes. I'll work on adding some tests for this later today or tomorrow.

@holetse, would it be practical to have an option for which locale to force in the connection, or do you think this is enough?

[justindotpub]

That fixed it for me! Thank you! I'll keep my eye out for the next bootleg release.

[rjanja]

Excellent! Thanks!

[holetse]

Thank you both for taking the time to dig into this issue!

@rjanja I think we should probably avoid forcing a locale at all if possible. In cases where its not set to something we can use, then maybe we set it to some reasonable UTF-8 option. To that end, I think having it be configurable is good, with a sane default and the ability to configure it to not alter the locale at all as well.