5

I'm running this command to run Drush which is basically a PHP CLI for Drupal, in the running container:

docker-compose -f ../docker-compose.test.yml exec php scripts/bin/vendor/drush.phar -r public_html status-report

The output if this command is fine, it's the list of status information about a specific Drupal instance in the container. I won't be pasting it here as it's long, and irrelevant.

Now let's filter this information by piping it into grep:

docker-compose -f ../docker-compose.test.yml exec php scripts/bin/vendor/drush.phar -r public_html status-report | grep -e Warning -e Error

The result is:

Cro  Error     L 
Gra  Warning   P 
HTT  Error     F 
HTT  Warning   T 
Dru  Warning   N 
XML  Error     L

Which is wrong, it looks like it has been cut to pieces, and most of it is missing.

Now, if we will disable allocating of pseudo-tty by adding -T flag:

docker-compose -f ../docker-compose.test.yml exec -T php scripts/bin/vendor/drush.phar -r public_html status-report | grep -e Warning -e Error

The output is correct:

Cron maintenance      Error     Last run 3 weeks 1 day ago                     
Gravatar              Warning   Potential issues                               
HTTP request status   Error     Fails                                          
HTTPRL - Non          Warning   This server does not handle hanging            
Drupal core update    Warning   No update data available                       
XML sitemap           Error     Last attempted generation on Tue, 04/18/2017

Why is that?

Bonus question, which probably will be answered by the answer to the previous one: Are there any important side effects of using -T?

Docker version 18.06.1-ce, build e68fc7a215
docker-compose version 1.22.0

UPDATE #1:

To simplify things I saved the correct output of the whole scripts/bin/vendor/drush.phar -r public_html status-report into a file test.txt and tried:

 docker-compose -f ../docker-compose.test.yml exec php cat test.txt | grep -e Warning -e Error

Interestingly the output is correct now with and witout -T, so it has to have something to do with Drush/php, although I'm still interested what can be a cause of this.

PHP 7.1.12 (cli) (built: Dec  1 2017 04:07:00) ( NTS )
Copyright (c) 1997-2017 The PHP Group
Zend Engine v3.1.0, Copyright (c) 1998-2017 Zend Technologies
    with Zend OPcache v7.1.12, Copyright (c) 1999-2017, by Zend Technologies
    with Xdebug v2.5.5, Copyright (c) 2002-2017, by Derick Rethans

Drush 8.1.17

UPDATE #2:

To isolate problem further I put all content in a PHP file, that is simply printing it, and after:

docker-compose -f ../docker-compose.test.yml exec php php php.php | grep -e Warning -e Error

I'm getting a correct output!

So it has to have something to do with how Drush is printing its messages, but I fail to see what it can be. That could be pretty interesting if we could figure this out.

UPDATE #3:

Ok guys, that's actual magic. The problem happens also with running drush without any commands, to list all available ones. The list of commands is broken when output is being piped, so this can be tested without actual Drupal instance.

Now I want to present you magic.

In drush, output for list of available commands in being generated in commands/core/help.drush.phpin function drush_core_help(). There is this call: drush_help_listing_print($command_categories); I looked into it. Inside is a call drush_print_table($rows, FALSE, array('name' => 20)); that is responsible for generating part of the output that's getting broken.

So inside of it, I decided to intercept the output, just before the last call to drush_print(), by adding simple file_put_contents('/var/www/html/data.txt', $output);

And now it's time for the absolutely magical part for me.

When I execute:

docker-compose -f ../docker-compose.test.yml exec php scripts/bin/vendor/drush/drush -r public_html

The last group of commands can be checked in this file, and in my case it's:

 adminrole-update      Update the administrator role permissions.                                                                                                  
 elysia-cron           Run all cron tasks in all active modules for specified site using elysia cron system. This replaces the standard "core-cron" drush handler. 
 generate-redirects    Create redirects.                                                                                                                           
 libraries-download    Download library files of registered libraries.                                                                                             
 (ldl, lib-download)                                                                                                                                               
 libraries-list (lls,  Show a list of registered libraries.                                                                                                        
 lib-list)

BUT, if I execute the same command, but the output will be piped or redirected, so for example:

docker-compose -f ../docker-compose.test.yml exec php scripts/bin/vendor/drush/drush -r public_html | cat

SOMETHING DIFFERENT WILL BE SAVED INTO A FILE:

 adminrole-update      U 
                       p 
                       d 
                       a 
                       t 
                       e 
                       t 
                       h 
                       e 
                       a 
                       d 
                       m 
                       i 
                       n 
                       i 
                       s 
                       t 
                       r 
                       a 
                       t 
                       o 
                       r 
                       r 
(and the rest of the broken output)

So the fact of piping/redirecting of the output, influences execution of the command, before the pipe/redirection actually happens.

How is that even possible? O_o

Łukasz Zaroda
  • 869
  • 2
  • 19
  • 55
  • Many programs change their behavior when their output is a pipe (or generally "not a tty"). `ls` for example changes to implicit `-1` behavior. Ostensibly this is to distingush between human friendly and program friendly presentations. It sounds like docker is doing the same here. – bishop Oct 28 '18 at 22:54
  • In another words, this is not magic: it is bog standard UNIX behavior effected by calling `isatty` on the output file descriptor. I will add that the shell already has setup piping before executing any of the programs, so those programs know a priori whether their stdout is a tty or not. – bishop Oct 28 '18 at 22:57
  • TIL, thanks! :) In this case I will still have to figure out how it relates to this specific setup. – Łukasz Zaroda Oct 28 '18 at 23:10
  • I was having a lot of problems with this and running with the `-T` options (`docker-compose exec -T ...`) fixed my problem – Jordan Mar 18 '19 at 05:51

2 Answers2

2

It's not uncommon for a command-line program to change its output presentation based on whether its output is a terminal, or not. For example, ls by itself, with no options, displays files in a columnar format. When piped, the output changes to a list of one-file-per-line. You can see this in the source code for GNU ls:

case LS_LS:
  /* This is for the 'ls' program.  */
  if (isatty (STDOUT_FILENO))
    {
      format = many_per_line;
      set_quoting_style (NULL, shell_escape_quoting_style);
      /* See description of qmark_funny_chars, above.  */
      qmark_funny_chars = true;
    }
  else
    {
      format = one_per_line;
      qmark_funny_chars = false;
    }
  break;

You can emulate the behavior of ls | ... with the explicit argument ls -1, and this too is not uncommon: programs that implicitly change their output presentation often provide a way to explicitly engage that alternate presentation.

Support for this isn't just a convention: it's actually a requirement for ls in POSIX:

The default format shall be to list one entry per line to standard output; the exceptions are to terminals or when one of the -C, -m, or -x options is specified. If the output is to a terminal, the format is implementation-defined.

This all may seem magical: how does ls know it's got a pipe following it since it comes before the pipe? The answer is quite simple, really: the shell parses the whole command line, sets up the pipes, and then forks the respective programs with the input/output wired to pipes appropriately.

So, what part of the command is doing the alternate presentation? I suspect it's an interaction between the environment of your exec and the column width calculation in drush. On my local environment, drush help | ... doesn't produce any unusual results. You might try piping to (or through) cat -vet to discover any unusual characters in the output.

That said, regarding docker-compose specifically: based on this thread, you're not the only one who has encountered this or a similar issue. I've not trawled the docker source code, but - generally - not allocating a pseudo-tty will make the other end act like a non-interactive shell, which means things like your .bash_profile won't run and you won't be able to read stdin in the run command. This can give the appearance of things not working.

The thread linked above mentions a work around of this form:

docker exec -i $(docker-compose ...) < input-file

which seems reasonable given the meaning of -i, but it also seems rather convoluted for basic scripting.

The fact that -T makes it work for you suggests to me that you have something in your .bash_profile (or similar login-shell-specific start up file) that's changing certain values (maybe COLUMNS) or altering the values in such a way as to have the observed deleterious effect. You might try removing everything from those files, then adding them back to see if any particular one causes the issue.

bishop
  • 37,830
  • 11
  • 104
  • 139
1

I didn't read that very detailed question, but from glancing over it, I'd say the -T option to the exec subcommand is essential if you want to process stdout and stderr in the environment where you execute docker-compose.

funky-future
  • 3,716
  • 1
  • 30
  • 43