pm-download output for contrib projects duplicated when called from drush make

Closed #1415836: Double output of log messages in drush backend invoke as a duplicate of this issue.

This cleared up the double messages for me, and didn't seem to cause any messages to be dropped either. Code looks good; committed. Let's re-open if any further problems crop up.

Reopening this as I am seeing double messages as the logs scroll by during the `phpunit makeTest.php`

@moshe: That's what jhedstrom is talking about over at #1434376-11: Errors not propagated, make silently "succeeds" but doesn't do anything -- we don't need both of these issues still open, but I'm not a maintainer so I'll leave that to y'all to sort out. ;)

I've been seeing these duplicate log entries while testing drush make with a variety of installation profiles. Here is one make file that consistently produces the failure, at least for me.

# cat /etc/drush/make/getid3.make.inc
core = 7.x
api = 2

; Modules
; Latest stable getid3 module
projects[] = "getid3"

; Libraries
; Latest stable getID3 library
libraries[getid3][download][type] = "get"
libraries[getid3][download][url] = "http://sourceforge.net/projects/getid3/files/latest/download?source=files"
libraries[getid3][directory_name] = "getid3"
libraries[getid3][overwrite] = TRUE

Results when run with drush make

# drush make --no-core /etc/drush/make/getid3.make.inc /tmp/testing
getid3-7.x-1.0 downloaded.                                                                                                                                                                  [ok]
getid3-7.x-1.0 downloaded.                                                                                                                                                                  [ok]
getid3 downloaded from http://sourceforge.net/projects/getid3/files/latest/download?source=files.  

Results when run with drush make --debug

# drush make --no-core --debug /etc/drush/make/getid3.make.inc /tmp/testing
Bootstrap to phase 0. [0.03 sec, 2.2 MB]                             [bootstrap]
Drush bootstrap phase : _drush_bootstrap_drush() [0.04 sec, 2.34 MB] [bootstrap]
Cache HIT cid: 5.0-dev-commandfiles-0-d855919b3fd468a8cb48278c0b0162e2 [0.07 sec, 2.35 MB]                                                                                                      [debug]
Bootstrap to phase 0. [0.18 sec, 5.17 MB]                                                                                                                                                   [bootstrap]
Bootstrap to phase 0. [0.21 sec, 5.17 MB]                                                                                                                                                   [bootstrap]
Found command: make (commandfile=make) [0.21 sec, 5.17 MB]                                                                                                                                  [bootstrap]
Loading release_info engine. [0.24 sec, 5.19 MB]                                                                                                                                               [notice]
Downloading release history from http://updates.drupal.org/release-history/getid3/7.x [0.24 sec, 5.33 MB]                                                                                      [notice]
http---updates.drupal.org-release-history-getid3-7.x retrieved from cache. [0.25 sec, 5.33 MB]                                                                                                 [notice]
Backend invoke: /usr/bin/php /opt/drush/drush.php --php=/usr/bin/php  make-process /tmp/make_tmp_1330276254_4f4a679e9fb74 --backend=2 2>&1 [0.3 sec, 5.36 MB]                                 [command]
/usr/bin/php /opt/drush/drush.php --php=/usr/bin/php  make-process /tmp/make_tmp_1330276254_4f4a679e9fb74 --backend=2 2>&1 [0.3 sec, 5.36 MB]                                                  [notice]
Bootstrap to phase 0. [0.58 sec, 5.17 MB]                                                                                                                                                   [bootstrap]
Bootstrap to phase 0. [0.61 sec, 5.18 MB]                                                                                                                                                   [bootstrap]
Found command: make-process (commandfile=make) [0.61 sec, 5.18 MB]                                                                                                                          [bootstrap]
Loading release_info engine. [0.62 sec, 5.19 MB]                                                                                                                                               [notice]
Backend invoke: /usr/bin/php /opt/drush/drush.php --php=/usr/bin/php  --yes --root= --uri= pm-download getid3-7.x-1.0                                                                         [command]
--destination=/tmp/make_tmp_1330276254_4f4a679e9fb74/__build__/sites/all/modules --package-handler=wget --variant=profile-only --cache --backend=2 2>&1 [0.68 sec, 5.33 MB]
/usr/bin/php /opt/drush/drush.php --php=/usr/bin/php  --yes --root= --uri= pm-download getid3-7.x-1.0   --destination=/tmp/make_tmp_1330276254_4f4a679e9fb74/__build__/sites/all/modules       [notice]
--package-handler=wget --variant=profile-only --cache --backend=2 2>&1 [0.68 sec, 5.33 MB]
Bootstrap to phase 0. [1.1 sec, 5.17 MB]                                                                                                                                                    [bootstrap]
Found command: pm-download (commandfile=pm) [1.14 sec, 5.18 MB]                                                                                                                             [bootstrap]
Loading version_control engine. [1.19 sec, 5.2 MB]                                                                                                                                             [notice]
Loading package_handler engine. [1.19 sec, 5.23 MB]                                                                                                                                            [notice]
Loading release_info engine. [1.26 sec, 5.25 MB]                                                                                                                                               [notice]
Including /opt/drush/commands/pm/download.pm.inc [1.27 sec, 5.35 MB]                                                                                                                        [bootstrap]
Downloading release history from http://updates.drupal.org/release-history/getid3/7.x [1.27 sec, 5.45 MB]                                                                                      [notice]
http---updates.drupal.org-release-history-getid3-7.x retrieved from cache. [1.28 sec, 5.45 MB]                                                                                                 [notice]
Downloading project getid3 to /tmp/drush_tmp_1330276255_4f4a679fa87e2 ... [1.29 sec, 5.45 MB]                                                                                                  [notice]
http---ftp.drupal.org-files-projects-getid3-7.x-1.0.tar.gz retrieved from cache. [1.29 sec, 5.45 MB]                                                                                           [notice]
Downloading getid3-7.x-1.0.tar.gz was successful. [1.29 sec, 5.45 MB]                                                                                                                          [notice]
Md5 checksum of getid3-7.x-1.0.tar.gz verified. [1.29 sec, 5.45 MB]                                                                                                                            [notice]
Verifying signature for svn version control engine. [1.44 sec, 5.46 MB]                                                                                                                         [debug]
Verifying signature for bzr version control engine. [1.54 sec, 5.46 MB]                                                                                                                         [debug]
Project getid3 (7.x-1.0) downloaded to /tmp/make_tmp_1330276254_4f4a679e9fb74/__build__/sites/all/modules/getid3. [1.57 sec, 5.46 MB]                                                       [success]
Command dispatch complete [1.57 sec, 5.42 MB]                                                                                                                                                  [notice]
Peak memory usage was 6.07 MB [1.57 sec, 5.42 MB]                                                                                                                                              [memory]
Load alias @self [1.57 sec, 5.43 MB]                                                                                                                                                           [notice]
Bootstrap to phase 0. [1.7 sec, 5.38 MB]                                                                                                                                                    [bootstrap]
Drush bootstrap phase : _drush_bootstrap_drush() [1.7 sec, 5.38 MB]                                                                                                                         [bootstrap]
Cache HIT cid: 5.0-dev-commandfiles-0-d855919b3fd468a8cb48278c0b0162e2 [1.7 sec, 5.38 MB]                                                                                                       [debug]
Bootstrap to phase 0. [1.7 sec, 5.38 MB]                                                                                                                                                    [bootstrap]
Found command: pm-download (commandfile=pm) [1.7 sec, 5.38 MB]                                                                                                                              [bootstrap]
Loading version_control engine. [1.7 sec, 5.39 MB]                                                                                                                                             [notice]
Loading package_handler engine. [1.7 sec, 5.39 MB]                                                                                                                                             [notice]
Loading release_info engine. [1.7 sec, 5.39 MB]                                                                                                                                                [notice]
Including /opt/drush/commands/pm/download.pm.inc [1.7 sec, 5.39 MB]                                                                                                                         [bootstrap]
Downloading release history from http://updates.drupal.org/release-history/getid3/7.x [1.7 sec, 5.39 MB]                                                                                       [notice]
http---updates.drupal.org-release-history-getid3-7.x retrieved from cache. [1.7 sec, 5.39 MB]                                                                                                  [notice]
Downloading project getid3 to /tmp/drush_tmp_1330276255_4f4a679fa87e2 ... [1.7 sec, 5.39 MB]                                                                                                   [notice]
http---ftp.drupal.org-files-projects-getid3-7.x-1.0.tar.gz retrieved from cache. [1.7 sec, 5.39 MB]                                                                                            [notice]
Downloading getid3-7.x-1.0.tar.gz was successful. [1.7 sec, 5.39 MB]                                                                                                                           [notice]
Md5 checksum of getid3-7.x-1.0.tar.gz verified. [1.7 sec, 5.39 MB]                                                                                                                             [notice]
Verifying signature for svn version control engine. [1.7 sec, 5.39 MB]                                                                                                                          [debug]
Verifying signature for bzr version control engine. [1.7 sec, 5.39 MB]                                                                                                                          [debug]
Project getid3 (7.x-1.0) downloaded to /tmp/make_tmp_1330276254_4f4a679e9fb74/__build__/sites/all/modules/getid3. [1.7 sec, 5.39 MB]                                                        [success]
Command dispatch complete [1.7 sec, 5.4 MB]                                                                                                                                                    [notice]
Peak memory usage was 6.07 MB [1.7 sec, 5.4 MB]                                                                                                                                                [memory]
getid3-7.x-1.0 downloaded. [1.7 sec, 5.38 MB]                                                                                                                                               [ok]
Command dispatch complete [1.7 sec, 5.33 MB]                                                                                                                                                   [notice]
Peak memory usage was 6.26 MB [1.7 sec, 5.33 MB]                                                                                                                                               [memory]
Load alias @self [1.7 sec, 5.34 MB]                                                                                                                                                            [notice]
Bootstrap to phase 0. [1.77 sec, 5.48 MB]                                                                                                                                                   [bootstrap]
Drush bootstrap phase : _drush_bootstrap_drush() [1.77 sec, 5.48 MB]                                                                                                                        [bootstrap]
Cache HIT cid: 5.0-dev-commandfiles-0-d855919b3fd468a8cb48278c0b0162e2 [1.77 sec, 5.49 MB]                                                                                                      [debug]
Bootstrap to phase 0. [1.77 sec, 5.49 MB]                                                                                                                                                   [bootstrap]
Bootstrap to phase 0. [1.77 sec, 5.49 MB]                                                                                                                                                   [bootstrap]
Found command: make-process (commandfile=make) [1.77 sec, 5.49 MB]                                                                                                                          [bootstrap]
Loading release_info engine. [1.77 sec, 5.49 MB]                                                                                                                                               [notice]
Backend invoke: /usr/bin/php /opt/drush/drush.php --php=/usr/bin/php  --yes --root= --uri= pm-download getid3-7.x-1.0                                                                         [command]
--destination=/tmp/make_tmp_1330276254_4f4a679e9fb74/__build__/sites/all/modules --package-handler=wget --variant=profile-only --cache --backend=2 2>&1 [1.77 sec, 5.49 MB]
/usr/bin/php /opt/drush/drush.php --php=/usr/bin/php  --yes --root= --uri= pm-download getid3-7.x-1.0   --destination=/tmp/make_tmp_1330276254_4f4a679e9fb74/__build__/sites/all/modules       [notice]
--package-handler=wget --variant=profile-only --cache --backend=2 2>&1 [1.77 sec, 5.49 MB]
Bootstrap to phase 0. [1.77 sec, 5.49 MB]                                                                                                                                                   [bootstrap]
Found command: pm-download (commandfile=pm) [1.77 sec, 5.49 MB]                                                                                                                             [bootstrap]
Loading version_control engine. [1.77 sec, 5.49 MB]                                                                                                                                            [notice]
Loading package_handler engine. [1.77 sec, 5.49 MB]                                                                                                                                            [notice]
Loading release_info engine. [1.77 sec, 5.49 MB]                                                                                                                                               [notice]
Including /opt/drush/commands/pm/download.pm.inc [1.77 sec, 5.5 MB]                                                                                                                         [bootstrap]
Downloading release history from http://updates.drupal.org/release-history/getid3/7.x [1.77 sec, 5.5 MB]                                                                                       [notice]
http---updates.drupal.org-release-history-getid3-7.x retrieved from cache. [1.77 sec, 5.5 MB]                                                                                                  [notice]
Downloading project getid3 to /tmp/drush_tmp_1330276255_4f4a679fa87e2 ... [1.77 sec, 5.5 MB]                                                                                                   [notice]
http---ftp.drupal.org-files-projects-getid3-7.x-1.0.tar.gz retrieved from cache. [1.77 sec, 5.5 MB]                                                                                            [notice]
Downloading getid3-7.x-1.0.tar.gz was successful. [1.77 sec, 5.5 MB]                                                                                                                           [notice]
Md5 checksum of getid3-7.x-1.0.tar.gz verified. [1.77 sec, 5.5 MB]                                                                                                                             [notice]
Verifying signature for svn version control engine. [1.77 sec, 5.5 MB]                                                                                                                          [debug]
Verifying signature for bzr version control engine. [1.77 sec, 5.5 MB]                                                                                                                          [debug]
Project getid3 (7.x-1.0) downloaded to /tmp/make_tmp_1330276254_4f4a679e9fb74/__build__/sites/all/modules/getid3. [1.77 sec, 5.5 MB]                                                        [success]
Command dispatch complete [1.77 sec, 5.5 MB]                                                                                                                                                   [notice]
Peak memory usage was 6.07 MB [1.78 sec, 5.5 MB]                                                                                                                                               [memory]
Load alias @self [1.78 sec, 5.5 MB]                                                                                                                                                            [notice]
Bootstrap to phase 0. [1.78 sec, 5.51 MB]                                                                                                                                                   [bootstrap]
Drush bootstrap phase : _drush_bootstrap_drush() [1.78 sec, 5.51 MB]                                                                                                                        [bootstrap]
Cache HIT cid: 5.0-dev-commandfiles-0-d855919b3fd468a8cb48278c0b0162e2 [1.78 sec, 5.51 MB]                                                                                                      [debug]
Bootstrap to phase 0. [1.78 sec, 5.51 MB]                                                                                                                                                   [bootstrap]
Found command: pm-download (commandfile=pm) [1.78 sec, 5.51 MB]                                                                                                                             [bootstrap]
Loading version_control engine. [1.78 sec, 5.51 MB]                                                                                                                                            [notice]
Loading package_handler engine. [1.78 sec, 5.51 MB]                                                                                                                                            [notice]
Loading release_info engine. [1.78 sec, 5.51 MB]                                                                                                                                               [notice]
Including /opt/drush/commands/pm/download.pm.inc [1.78 sec, 5.51 MB]                                                                                                                        [bootstrap]
Downloading release history from http://updates.drupal.org/release-history/getid3/7.x [1.78 sec, 5.51 MB]                                                                                      [notice]
http---updates.drupal.org-release-history-getid3-7.x retrieved from cache. [1.78 sec, 5.51 MB]                                                                                                 [notice]
Downloading project getid3 to /tmp/drush_tmp_1330276255_4f4a679fa87e2 ... [1.78 sec, 5.51 MB]                                                                                                  [notice]
http---ftp.drupal.org-files-projects-getid3-7.x-1.0.tar.gz retrieved from cache. [1.78 sec, 5.51 MB]                                                                                           [notice]
Downloading getid3-7.x-1.0.tar.gz was successful. [1.78 sec, 5.52 MB]                                                                                                                          [notice]
Md5 checksum of getid3-7.x-1.0.tar.gz verified. [1.78 sec, 5.52 MB]                                                                                                                            [notice]
Verifying signature for svn version control engine. [1.78 sec, 5.52 MB]                                                                                                                         [debug]
Verifying signature for bzr version control engine. [1.78 sec, 5.52 MB]                                                                                                                         [debug]
Project getid3 (7.x-1.0) downloaded to /tmp/make_tmp_1330276254_4f4a679e9fb74/__build__/sites/all/modules/getid3. [1.78 sec, 5.52 MB]                                                       [success]
Command dispatch complete [1.78 sec, 5.52 MB]                                                                                                                                                  [notice]
Peak memory usage was 6.07 MB [1.78 sec, 5.52 MB]                                                                                                                                              [memory]
getid3-7.x-1.0 downloaded. [1.78 sec, 5.52 MB]                                                                                                                                              [ok]
Command dispatch complete [1.78 sec, 5.52 MB]                                                                                                                                                  [notice]
Peak memory usage was 6.26 MB [1.78 sec, 5.52 MB]                                                                                                                                              [memory]
Executing: which wget
  /usr/bin/wget
Executing: wget -q --timeout=30 -O /tmp/download_fileEvPJs9 'http://sourceforge.net/projects/getid3/files/latest/download?source=files'
Calling is_readable(/tmp/download_fileEvPJs9) [3.31 sec, 5.44 MB]                                                                                                                               [debug]
Calling is_writable(/tmp/make_tmp_1330276254_4f4a679e9fb74) [3.31 sec, 5.44 MB]                                                                                                                 [debug]
Calling rename(/tmp/download_fileEvPJs9, /tmp/make_tmp_1330276254_4f4a679e9fb74/download) [3.31 sec, 5.44 MB]                                                                                   [debug]
getid3 downloaded from http://sourceforge.net/projects/getid3/files/latest/download?source=files. [3.32 sec, 5.44 MB]                                                                       [ok]
Executing: unzip /tmp/make_tmp_1330276254_4f4a679e9fb74/download -d /tmp/make_tmp_1330276254_4f4a679e9fb74/__unzip__
  Archive:  /tmp/make_tmp_1330276254_4f4a679e9fb74/download
  getID3() v1.9.3-20111213
  James Heinrich
  info@getid3.org
  http://getid3.sourceforge.net
  http://www.getid3.org
    inflating: /tmp/make_tmp_1330276254_4f4a679e9fb74/__unzip__/license.txt
 ...snip...
    inflating: /tmp/make_tmp_1330276254_4f4a679e9fb74/__unzip__/license.commercial.txt
Executing: ls /tmp/make_tmp_1330276254_4f4a679e9fb74/__unzip__
  changelog.txt
  demos
  dependencies.txt
  getid3
  helperapps
  license.commercial.txt
  license.txt
  readme.txt
  structure.txt
Executing: rm -rf /tmp/make_tmp_1330276254_4f4a679e9fb74/__build__/sites/all/libraries/getid3
Executing: mv /tmp/make_tmp_1330276254_4f4a679e9fb74/__unzip__ /tmp/make_tmp_1330276254_4f4a679e9fb74/__build__/sites/all/libraries/getid3
Executing: rm /tmp/make_tmp_1330276254_4f4a679e9fb74/download
Executing: mv /tmp/make_tmp_1330276254_4f4a679e9fb74/__build__ /tmp/make_tmp_1330276254_4f4a679e9fb74/testing
Executing: cp -Rf /tmp/make_tmp_1330276254_4f4a679e9fb74/testing /tmp
Command dispatch complete [3.78 sec, 5.41 MB]                                                                                                                                                  [notice]
Peak memory usage was 6.28 MB [3.78 sec, 5.41 MB]                                                                                                                                              [memory]

It appears to be downloading the getid3 module from drupal.org twice, not just displaying a duplicate message. Hope this information helps in giving the maintainers a direction to look.

My drush environment:

# git status
# On branch master
nothing to commit (working directory clean)

# git show
commit 35d57c7e57d42027c5b365a8fdbf944a45b19aa6
Author: Moshe Weitzman <weitzman@tejasa.com>
Date:   Sun Feb 26 11:51:29 2012 -0500

    Issue #1450374 by iMiksu: Fixed Secondary patching command does not loop thru patch levels.

# drush status
 PHP configuration     :  /etc/php5/cli/php.ini                                                                                              
 Drush version         :  5.0-dev                                                                                                            
 Drush configuration   :                                                                                                                     
 Drush alias files     :  /etc/drush/publisher.alias.drushrc.php /etc/drush/developer.alias.drushrc.php /etc/drush/drupal7.alias.drushrc.php 

Compare:

$ drush ev 'drush_invoke_process('@self',"cron",array(),array(),array("integrate"=>TRUE));'
Cron run successful.                                                 [success]
Cron run successful.                                                 [success]

With:

$ drush ev 'drush_invoke_process('@self',"cron",array(),array(),array("integrate"=>FALSE));'
Cron run successful.                                                 [success]

This is a bug in the handling of 'integrate' => TRUE. I have not had a chance to look into it yet.

@greg.1.anderson -- I ran your first command on one of my sites with the same result. I then tried running with --debug without any apparent errors. Frustrating to try and debug. I tried unsuccessfully to apply jhedstrom's patch #1. I tried a --3way merge, but even that wouldn't work. I'm wondering if we don't have two separate problems. Mine seems to only affect drush make. I wasn't giving it a high priority since it seems to be benign, but it does add additional load on the servers.

It could be that #7 is a different issue, esp. if sections of the code are running twice. In the original issue, the code only runs once, but the messages are emitted twice.

I simplified my getid3.make file to only include the getid3 module (eliminated the library files).

core = 7.x
api = 2

; Modules
; Latest stable getid3 module
projects[] = "getid3"

The --debug results seem to show that some code is executed twice. I just can't figure out why.
This time I made sure to clear all caches before running the drush make command.

# drush cc all
'all' cache was cleared                                                                                                                                                                        [success]
# drush make -y --no-core --debug /opt/getid3.make /tmp/testing

Bootstrap to phase 0. [0.05 sec, 2.2 MB]                             [bootstrap]
Drush bootstrap phase : _drush_bootstrap_drush() [0.06 sec, 2.34 MB] [bootstrap]
Cache MISS cid: 5.0-dev-commandfiles-0-d855919b3fd468a8cb48278c0b0162e2 [0.1 sec, 2.35 MB]                                                                                                         [debug]
Cache SET cid: 5.0-dev-commandfiles-0-d855919b3fd468a8cb48278c0b0162e2 [0.11 sec, 2.36 MB]                                                                                                         [debug]
Bootstrap to phase 0. [0.18 sec, 5.17 MB]                                                                                                                                                      [bootstrap]
Bootstrap to phase 0. [0.2 sec, 5.18 MB]                                                                                                                                                       [bootstrap]
Found command: make (commandfile=make) [0.2 sec, 5.18 MB]                                                                                                                                      [bootstrap]
Loading release_info engine. [0.23 sec, 5.19 MB]                                                                                                                                                  [notice]
Downloading release history from http://updates.drupal.org/release-history/getid3/7.x [0.24 sec, 5.33 MB]                                                                                         [notice]
http---updates.drupal.org-release-history-getid3-7.x retrieved from cache. [0.24 sec, 5.33 MB]                                                                                                    [notice]
Backend invoke: /usr/bin/php /opt/drush/drush.php --php=/usr/bin/php  make-process /tmp/make_tmp_1330368390_4f4bcf867a0aa --backend=2 2>&1 [0.29 sec, 5.36 MB]                                   [command]
/usr/bin/php /opt/drush/drush.php --php=/usr/bin/php  make-process /tmp/make_tmp_1330368390_4f4bcf867a0aa --backend=2 2>&1 [0.29 sec, 5.36 MB]                                                    [notice]
Bootstrap to phase 0. [0.6 sec, 5.17 MB]                                                                                                                                                       [bootstrap]
Bootstrap to phase 0. [0.63 sec, 5.18 MB]                                                                                                                                                      [bootstrap]
Found command: make-process (commandfile=make) [0.63 sec, 5.18 MB]                                                                                                                             [bootstrap]
Loading release_info engine. [0.64 sec, 5.19 MB]                                                                                                                                                  [notice]
Backend invoke: /usr/bin/php /opt/drush/drush.php --php=/usr/bin/php  --yes --root= --uri= pm-download getid3-7.x-1.0                                                                            [command]
--destination=/tmp/make_tmp_1330368390_4f4bcf867a0aa/__build__/sites/all/modules --package-handler=wget --variant=profile-only --cache --backend=2 2>&1 [0.7 sec, 5.33 MB]
/usr/bin/php /opt/drush/drush.php --php=/usr/bin/php  --yes --root= --uri= pm-download getid3-7.x-1.0   --destination=/tmp/make_tmp_1330368390_4f4bcf867a0aa/__build__/sites/all/modules          [notice]
--package-handler=wget --variant=profile-only --cache --backend=2 2>&1 [0.71 sec, 5.33 MB]
Bootstrap to phase 0. [1.25 sec, 5.17 MB]                                                                                                                                                      [bootstrap]
Found command: pm-download (commandfile=pm) [1.32 sec, 5.18 MB]                                                                                                                                [bootstrap]
Loading version_control engine. [1.34 sec, 5.2 MB]                                                                                                                                                [notice]
Loading package_handler engine. [1.34 sec, 5.23 MB]                                                                                                                                               [notice]
Loading release_info engine. [1.41 sec, 5.25 MB]                                                                                                                                                  [notice]
Including /opt/drush/commands/pm/download.pm.inc [1.42 sec, 5.35 MB]                                                                                                                           [bootstrap]
Downloading release history from http://updates.drupal.org/release-history/getid3/7.x [1.43 sec, 5.45 MB]                                                                                         [notice]
http---updates.drupal.org-release-history-getid3-7.x retrieved from cache. [1.43 sec, 5.45 MB]                                                                                                    [notice]
Downloading project getid3 to /tmp/drush_tmp_1330368391_4f4bcf87aa9fd ... [1.45 sec, 5.45 MB]                                                                                                     [notice]
http---ftp.drupal.org-files-projects-getid3-7.x-1.0.tar.gz retrieved from cache. [1.45 sec, 5.45 MB]                                                                                              [notice]
Downloading getid3-7.x-1.0.tar.gz was successful. [1.45 sec, 5.45 MB]                                                                                                                             [notice]
Md5 checksum of getid3-7.x-1.0.tar.gz verified. [1.45 sec, 5.45 MB]                                                                                                                               [notice]
Verifying signature for svn version control engine. [1.6 sec, 5.46 MB]                                                                                                                             [debug]
Verifying signature for bzr version control engine. [1.7 sec, 5.46 MB]                                                                                                                             [debug]
Project getid3 (7.x-1.0) downloaded to /tmp/make_tmp_1330368390_4f4bcf867a0aa/__build__/sites/all/modules/getid3. [1.74 sec, 5.46 MB]                                                          [success]
Command dispatch complete [1.74 sec, 5.42 MB]                                                                                                                                                     [notice]
Peak memory usage was 6.07 MB [1.74 sec, 5.42 MB]                                                                                                                                                 [memory]
Load alias @self [1.74 sec, 5.43 MB]                                                                                                                                                              [notice]
Bootstrap to phase 0. [1.88 sec, 5.38 MB]                                                                                                                                                      [bootstrap]
Drush bootstrap phase : _drush_bootstrap_drush() [1.88 sec, 5.38 MB]                                                                                                                           [bootstrap]
Cache HIT cid: 5.0-dev-commandfiles-0-d855919b3fd468a8cb48278c0b0162e2 [1.88 sec, 5.38 MB]                                                                                                         [debug]
Bootstrap to phase 0. [1.88 sec, 5.38 MB]                                                                                                                                                      [bootstrap]
Found command: pm-download (commandfile=pm) [1.88 sec, 5.38 MB]                                                                                                                                [bootstrap]
Loading version_control engine. [1.88 sec, 5.39 MB]                                                                                                                                               [notice]
Loading package_handler engine. [1.88 sec, 5.39 MB]                                                                                                                                               [notice]
Loading release_info engine. [1.88 sec, 5.39 MB]                                                                                                                                                  [notice]
Including /opt/drush/commands/pm/download.pm.inc [1.88 sec, 5.39 MB]                                                                                                                           [bootstrap]
Downloading release history from http://updates.drupal.org/release-history/getid3/7.x [1.88 sec, 5.39 MB]                                                                                         [notice]
http---updates.drupal.org-release-history-getid3-7.x retrieved from cache. [1.88 sec, 5.39 MB]                                                                                                    [notice]
Downloading project getid3 to /tmp/drush_tmp_1330368391_4f4bcf87aa9fd ... [1.88 sec, 5.39 MB]                                                                                                     [notice]
http---ftp.drupal.org-files-projects-getid3-7.x-1.0.tar.gz retrieved from cache. [1.88 sec, 5.39 MB]                                                                                              [notice]
Downloading getid3-7.x-1.0.tar.gz was successful. [1.88 sec, 5.39 MB]                                                                                                                             [notice]
Md5 checksum of getid3-7.x-1.0.tar.gz verified. [1.88 sec, 5.39 MB]                                                                                                                               [notice]
Verifying signature for svn version control engine. [1.88 sec, 5.39 MB]                                                                                                                            [debug]
Verifying signature for bzr version control engine. [1.88 sec, 5.39 MB]                                                                                                                            [debug]
Project getid3 (7.x-1.0) downloaded to /tmp/make_tmp_1330368390_4f4bcf867a0aa/__build__/sites/all/modules/getid3. [1.88 sec, 5.4 MB]                                                           [success]
Command dispatch complete [1.88 sec, 5.4 MB]                                                                                                                                                      [notice]
Peak memory usage was 6.07 MB [1.88 sec, 5.4 MB]                                                                                                                                                  [memory]
getid3-7.x-1.0 downloaded. [1.88 sec, 5.38 MB]                                                                                                                                                 [ok]
Command dispatch complete [1.88 sec, 5.33 MB]                                                                                                                                                     [notice]
Peak memory usage was 6.26 MB [1.88 sec, 5.34 MB]                                                                                                                                                 [memory]
Load alias @self [1.88 sec, 5.34 MB]                                                                                                                                                              [notice]
Bootstrap to phase 0. [1.95 sec, 5.49 MB]                                                                                                                                                      [bootstrap]
Drush bootstrap phase : _drush_bootstrap_drush() [1.95 sec, 5.49 MB]                                                                                                                           [bootstrap]
Cache HIT cid: 5.0-dev-commandfiles-0-d855919b3fd468a8cb48278c0b0162e2 [1.95 sec, 5.49 MB]                                                                                                         [debug]
Bootstrap to phase 0. [1.95 sec, 5.49 MB]                                                                                                                                                      [bootstrap]
Bootstrap to phase 0. [1.95 sec, 5.49 MB]                                                                                                                                                      [bootstrap]
Found command: make-process (commandfile=make) [1.95 sec, 5.49 MB]                                                                                                                             [bootstrap]
Loading release_info engine. [1.95 sec, 5.49 MB]                                                                                                                                                  [notice]
Backend invoke: /usr/bin/php /opt/drush/drush.php --php=/usr/bin/php  --yes --root= --uri= pm-download getid3-7.x-1.0                                                                            [command]
--destination=/tmp/make_tmp_1330368390_4f4bcf867a0aa/__build__/sites/all/modules --package-handler=wget --variant=profile-only --cache --backend=2 2>&1 [1.95 sec, 5.49 MB]
/usr/bin/php /opt/drush/drush.php --php=/usr/bin/php  --yes --root= --uri= pm-download getid3-7.x-1.0   --destination=/tmp/make_tmp_1330368390_4f4bcf867a0aa/__build__/sites/all/modules          [notice]
--package-handler=wget --variant=profile-only --cache --backend=2 2>&1 [1.95 sec, 5.49 MB]
Bootstrap to phase 0. [1.95 sec, 5.49 MB]                                                                                                                                                      [bootstrap]
Found command: pm-download (commandfile=pm) [1.95 sec, 5.49 MB]                                                                                                                                [bootstrap]
Loading version_control engine. [1.95 sec, 5.49 MB]                                                                                                                                               [notice]
Loading package_handler engine. [1.95 sec, 5.5 MB]                                                                                                                                                [notice]
Loading release_info engine. [1.95 sec, 5.5 MB]                                                                                                                                                   [notice]
Including /opt/drush/commands/pm/download.pm.inc [1.95 sec, 5.5 MB]                                                                                                                            [bootstrap]
Downloading release history from http://updates.drupal.org/release-history/getid3/7.x [1.95 sec, 5.5 MB]                                                                                          [notice]
http---updates.drupal.org-release-history-getid3-7.x retrieved from cache. [1.95 sec, 5.5 MB]                                                                                                     [notice]
Downloading project getid3 to /tmp/drush_tmp_1330368391_4f4bcf87aa9fd ... [1.95 sec, 5.5 MB]                                                                                                      [notice]
http---ftp.drupal.org-files-projects-getid3-7.x-1.0.tar.gz retrieved from cache. [1.95 sec, 5.5 MB]                                                                                               [notice]
Downloading getid3-7.x-1.0.tar.gz was successful. [1.95 sec, 5.5 MB]                                                                                                                              [notice]
Md5 checksum of getid3-7.x-1.0.tar.gz verified. [1.95 sec, 5.5 MB]                                                                                                                                [notice]
Verifying signature for svn version control engine. [1.95 sec, 5.5 MB]                                                                                                                             [debug]
Verifying signature for bzr version control engine. [1.95 sec, 5.5 MB]                                                                                                                             [debug]
Project getid3 (7.x-1.0) downloaded to /tmp/make_tmp_1330368390_4f4bcf867a0aa/__build__/sites/all/modules/getid3. [1.95 sec, 5.5 MB]                                                           [success]
Command dispatch complete [1.95 sec, 5.5 MB]                                                                                                                                                      [notice]
Peak memory usage was 6.07 MB [1.95 sec, 5.51 MB]                                                                                                                                                 [memory]
Load alias @self [1.95 sec, 5.51 MB]                                                                                                                                                              [notice]
Bootstrap to phase 0. [1.95 sec, 5.51 MB]                                                                                                                                                      [bootstrap]
Drush bootstrap phase : _drush_bootstrap_drush() [1.96 sec, 5.51 MB]                                                                                                                           [bootstrap]
Cache HIT cid: 5.0-dev-commandfiles-0-d855919b3fd468a8cb48278c0b0162e2 [1.96 sec, 5.51 MB]                                                                                                         [debug]
Bootstrap to phase 0. [1.96 sec, 5.51 MB]                                                                                                                                                      [bootstrap]
Found command: pm-download (commandfile=pm) [1.96 sec, 5.51 MB]                                                                                                                                [bootstrap]
Loading version_control engine. [1.96 sec, 5.51 MB]                                                                                                                                               [notice]
Loading package_handler engine. [1.96 sec, 5.51 MB]                                                                                                                                               [notice]
Loading release_info engine. [1.96 sec, 5.51 MB]                                                                                                                                                  [notice]
Including /opt/drush/commands/pm/download.pm.inc [1.96 sec, 5.51 MB]                                                                                                                           [bootstrap]
Downloading release history from http://updates.drupal.org/release-history/getid3/7.x [1.96 sec, 5.51 MB]                                                                                         [notice]
http---updates.drupal.org-release-history-getid3-7.x retrieved from cache. [1.96 sec, 5.51 MB]                                                                                                    [notice]
Downloading project getid3 to /tmp/drush_tmp_1330368391_4f4bcf87aa9fd ... [1.96 sec, 5.52 MB]                                                                                                     [notice]
http---ftp.drupal.org-files-projects-getid3-7.x-1.0.tar.gz retrieved from cache. [1.96 sec, 5.52 MB]                                                                                              [notice]
Downloading getid3-7.x-1.0.tar.gz was successful. [1.96 sec, 5.52 MB]                                                                                                                             [notice]
Md5 checksum of getid3-7.x-1.0.tar.gz verified. [1.96 sec, 5.52 MB]                                                                                                                               [notice]
Verifying signature for svn version control engine. [1.96 sec, 5.52 MB]                                                                                                                            [debug]
Verifying signature for bzr version control engine. [1.96 sec, 5.52 MB]                                                                                                                            [debug]
Project getid3 (7.x-1.0) downloaded to /tmp/make_tmp_1330368390_4f4bcf867a0aa/__build__/sites/all/modules/getid3. [1.96 sec, 5.52 MB]                                                          [success]
Command dispatch complete [1.96 sec, 5.52 MB]                                                                                                                                                     [notice]
Peak memory usage was 6.07 MB [1.96 sec, 5.52 MB]                                                                                                                                                 [memory]
getid3-7.x-1.0 downloaded. [1.96 sec, 5.52 MB]                                                                                                                                                 [ok]
Command dispatch complete [1.96 sec, 5.52 MB]                                                                                                                                                     [notice]
Peak memory usage was 6.26 MB [1.96 sec, 5.52 MB]                                                                                                                                                 [memory]
Executing: mv /tmp/make_tmp_1330368390_4f4bcf867a0aa/__build__ /tmp/make_tmp_1330368390_4f4bcf867a0aa/testing
Executing: cp -Rf /tmp/make_tmp_1330368390_4f4bcf867a0aa/testing /tmp
Command dispatch complete [2.04 sec, 5.41 MB]                                                                                                                                                     [notice]
Peak memory usage was 6.28 MB [2.04 sec, 5.41 MB]                                                                                                                                                 [memory]

Here is a patch that clears up the double-output of log messages when 'integrate' is true. The existing logic for suppressing double output was not quite right; it worked in verbose or debug mode, but not otherwise (c.f. #11). This patch insures that drush_log is always called when 'integrate' is set, and allows the log message to be printed there; the double-output is now suppressed in drush_backend_packet_log by skipping the call to drush_get_context _drush_print_log when 'integrate' is set. Maybe I should have wrapped the 'if' around the callback call rather than introducing a no-op function. Stylistic changes can be made if this does the trick; I'm done with fiddling for tonight.

I did not investigate #14, but suspect that it may be a separate issue.

Looks good to me.

Committed a cleaned-up version of #15. 699f75e.

Please re-open if duplicate log messages are observed, or if log messages disappear completely. Please open a new issue for defects where the same code is called multiple times.

@greg.1.anderson - Your patch #15 does indeed suppress the double printing of the log message, however --debug still shows that code to download and extract the package is being executed twice. I can't think of a reason why this is necessary. It doesn't seem to cause a problem with the resulting build and on the second pass the project is downloaded from cache, so there is no load impact on the servers. Still it would be nice to fix this before the 5.0 release and perhaps improve performance a bit. I've attached a marked up log of output from drush make --debug showing the two repeated segments.

Sorry, I started composing #18 before you posted #17. I'll open a new issue for the repeated code.

My fix in #17 was inappropriate. The line I removed is the one that was printing out the log messages in real time; now that I took it out, Drush does not print any log output until backend_invoke finishes. This is undesirable. I need to rework this and figure out the best way to suppress the output at integrate time.

Committed 6c7f8a1. Note that this also fixes another discrepancy between Drush-5 and Drush-4; we now omit log messages from the console, but include them in the backend results, when integrate is FALSE, just like Drush-4.

Forgot to set status.