broken IPC communication on Drupal 6 (AKA "welcome email not being sent")

So this is rather weird. While trying to debug this, I was able to propagate a client_email setting from frontend to backend using the commandline:

sh-3.1$ /usr/bin/drush --verbose=2 --debug --root='/var/hostmaster/drupal-6.12' --uri=http://hostmaster.koumbit.net hosting task 1688
[...]
Running: php /usr/bin/drush                                            [command]
--aliases='testd62-hostmaster-koumbit-net.site.koumbit.net,www.testd62.hostmaster.koumbit.net'
--client_id='1' --client_email='webmaster@localhost' --db_id='2'
--profile='default' --platform='1517'
--publish_path='/var/hostmaster/drupal-6.12' --site_id='1687'
--language='en' --drush_path='/usr/bin/drush' --web_id='3'
--web_host='localhost' --web_ip='127.0.0.1'
--script_user='hostmaster' --root='/var/hostmaster/drupal-6.12'
'provision' 'install' 'testd62.hostmaster.koumbit.net' --backend [1
sec]
[...]
sh-3.1$ grep client_email drushrc.php 
$options['client_email'] = 'webmaster@localhost';

Yet doing the same thing without running the task directly but doing it through the cronjob doesn't create the proper client_email in the drushrc:

sh-3.1$ grep client_email ../testd63.hostmaster.koumbit.net/drushrc.php
$options['client_email'] = NULL;

I tried to enable debugging in the backend to figure out what was going on. That had a really weird effect. Here's what I tried:

Index: backend.inc
===================================================================
RCS file: /cvs/drupal/contributions/modules/drush/includes/backend.inc,v
retrieving revision 1.15
diff -u -r1.15 backend.inc
--- backend.inc 20 May 2009 21:26:55 -0000      1.15
+++ backend.inc 24 Jun 2009 00:32:50 -0000
@@ -346,7 +346,9 @@
  * Use this if you don't care what the return value of the command may be.
  */
 function drush_backend_fork($command, $data, $drush_path = null, $hostname = null, $username = null) {
-  $data['quiet'] = TRUE;
+  $data['quiet'] = FALSE;
+  $data['verbose'] = 2;
+  $data['debug'] = TRUE;
   $cmd = "(" . _drush_backend_generate_command($command, $data, 'GET', $drush_path, $hostname, $username) . ' &) > /dev/null';
   drush_log(dt("Forking : !cmd", array('!cmd' => $cmd)));
   system($cmd);

The backend command was called properly, but exhausted all available memory:

Running: php /usr/bin/drush --aliases='testjfkdslafs-hostmaster-koumbit-ne... (Expand)Running: php /usr/bin/drush --aliases='testjfkdslafs-hostmaster-koumbit-net.site.koumbit.net,www.testjfkdslafs.hostmaster.koumbit.net' --client_id='1' --client_email='webmaster@localhost' --db_id='2' --profile='single_user_blog' --platform='1517' --publish_path='/var/hostmaster/drupal-6.12' --site_id='1695' --language='en' --drush_path='/usr/bin/drush' --web_id='3' --web_host='localhost' --web_ip='127.0.0.1' --script_user='hostmaster' --root='/var/hostmaster/drupal-6.12' 'provision' 'install' 'testjfkdslafs.hostmaster.koumbit.net' --backend
The command could not be executed succesfully (returned: Fatal error: Allowed memory size of 67108864 bytes exhausted (tried to allocate 83 bytes) in /var/hostmaster/drupal-6.12/includes/module.inc on line 177 , code: 0)
Removing task from hosting queue
An error occurred at function : drush_hosting_hosting_task
Changes for drush_hosting_hosting_task module have been rolled back.
Command dispatch complete

I tried doing an strace on it and it seemed it was locked in an infinite loop, but I am not sure. Here's the last snippet i got from it:

open("sites/all/modules/og/modules/og_views/includes", O_RDONLY|O_NONBLOCK|O_DIRECTORY) = 9
fstat(9, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
fcntl(9, F_SETFD, FD_CLOEXEC)           = 0
getdents64(9, /* 24 entries */, 4096)   = 1456
stat("sites/all/modules/og/modules/og_views/includes/og_views_handler_field_og_selective.inc", {st_mode=S_IFREG|0644, st_size=277, ...}) = 0

In fact, running in verbose, it seems the single_user_blog profile effectively loops:

Running profile specific task : profile [6.71 sec]                      [notice]
Running profile specific task : pathauto_setup [8.873 sec]              [notice]
Running profile specific task : pathauto_setup [9.166 sec]              [notice]
Running profile specific task : pathauto_setup [9.435 sec]              [notice]
...

So this is not necessarly related. Nevertheless: the install task runs fine (ie. the install profile is not passed to the backend) when ran without --quiet, so maybe the issue lies there.

I confirm that the backend patch above fixes the issue. I'll try to figure out if it's just a matter of not using --quiet.

A little context first... As you may well know, Aegir uses heavily the interprocess communcation features to propagate information between drush calls. One of the things that is send from the frontend (the hosting module) to the backend (the provision "command set") is the client_email when a site is created. This in turn is used to send the welcome email by the backend. After upgrading the frontend from Drupal 5 to Drupal 6, I noticed sites were not created properly anymore. The welcome link wasn't sent, the profile chosen wasn't applied and a bunch of other weird things are happening.

I think this is due to the backend being to picky or the frontend changing in a radical way that the backend is not expecting. I quickly reviewed (again) the changed between Hosting D5 and D6 and couldn't find anything really related to IPC, so I don't know how to fix the problem in the frontend. I can fix it in the backend, however...

So here's the patch that fixes the frontend/backend communication for me. I think this would need to be reviewed by Adrian and the Drush team so I'll put this up in the Drush queue, but this is highly Aegir-specific.

I wonder why that --quiet was there for in the first place...

Adrian says the fix shouldn't be in the backend, so I'm throwing this back at hosting.

I just updated to cvs HEAD everywhere (but drush, which is installed as my 2.0 debian package) and I still get the bug:

anarcat@hostmaster:/var/hostmaster/drupal-6.12/sites/testd666.hostmaster.koumbit.net$ grep client_email drushrc.php 
$options['client_email'] = NULL

I've done what could be an interesting test: I tried applying the above patch, and run two more tasks. A verify of a site that was created before the task (with client_email = NULL) and an install of a new site. The install succeeded and has the proper client_email, but the verify didn't fix the client_email.

Just a shot in the dark i guess...

I installed a new platform, verified it, and the issue went away.

Let's release this damn thing.

This bug is still present in 0.3. It is intermittent: Steve Parks was able to reproduce it in #524916: User not defined on new platform, but only momentarily. Still, he did reproduce it, and whether it's a local problem, a documentation problem or an actual bug in aegir or the IPC, the problem *does* exist and we need to find a way to fix it, or at the very least figure out exactly how and why it happens.

So I'm reopening that horrible issue again. It will manifest itself only by the login_url not showing up in the task log and the welcome email not being sent, amongst other things. There are various workarounds that can be used for the welcome email issue (such as #567094: Password reset link).

@omega8cc - this seems to be a different issue. The one we are talking about here is that no email whatsoever is sent out. It also happens that the login link doesn't show up in the task log. So I think your issue is different.

For the record, I have also received empty emails recently. I have no idea if the two issues (empty and no email) are related.

at any rate, the key idea here is that we need a way to reproduce interprocess issues much more easily. normally, errors should be caught and returned to the task log, but for some reason, sometimes that doesn't happen. I have seen long before issues with memory that wouldn't show up in the task log, and there are probably other such conditions that are not properly handled.

please do test to death this issue, and find the way to reproduce it. any information will help.

I'm seeing this bug... again! It's intermittent, on the same platform, some sites get created properly, some don't. I stumbled upon this bug here: #597738: We shouldn't provision install more than once on the same site.