drush vnew fails during "Verify Aegir front-end"

[ghost]

drush vnew fails during "Verify Aegir front-end"

I cannot deploy new VMs anymore with the current HEAD of Valkyrie. The process goes fine up to the Verify Aegir front-end step which fails (100% reproducible):

[valkyrie@sz6 ~]$ drush vnew shiftmedia
[…]
==> valkyrie: NOTIFIED: [geerlingguy.php | restart webserver] ******************************* 
==> valkyrie: changed: [localhost]
==> valkyrie: 
==> valkyrie: NOTIFIED: [geerlingguy.php | restart php-fpm] ********************************* 
==> valkyrie: skipping: [localhost]
==> valkyrie: 
==> valkyrie: NOTIFIED: [geerlingguy.mysql | restart mysql] ********************************* 
==> valkyrie: changed: [localhost]
==> valkyrie: 
==> valkyrie: 
==> valkyrie: NOTIFIED: [getvalkyrie.aegir | Verify Aegir front-end] ************************ 
==> valkyrie: failed: [localhost] => {"changed": true, "cmd": "drush @hm cc drush && drush @hm hosting-task @hostmaster verify --force", "delta": "0:00:03.380211", "end": "2015-04-02 09:34:06.994369", "rc": 1, "start": "2015-04-02 09:34:03.614158", "warnings": []}                                                                                                            
==> valkyrie: stderr: 'drush' cache was cleared.                                             [success]
==> valkyrie: The drush command 'hosting-task @hostmaster verify' could not be         [error]                              
==> valkyrie: found.  Run `drush cache-clear drush` to clear the commandfile cache                                          
==> valkyrie: if you have installed new extensions.                                                                         
==> valkyrie: Drush was not able to start (bootstrap) the Drupal database.             [error]                              
==> valkyrie: Hint: This may occur when Drush is trying to:                                                                 
==> valkyrie:  * bootstrap a site that has not been installed or does not have a                                            
==> valkyrie: configured database. In this case you can select another site with a                                          
==> valkyrie: working database setup by specifying the URI to use with the --uri                                            
==> valkyrie: parameter on the command line. See `drush topic docs-aliases` for                                             
==> valkyrie: details.                                                                                                      
==> valkyrie:  * connect the database through a socket. The socket file may be                                              
==> valkyrie: wrong or the php-cli may have no access to it in a jailed shell. See                                          
==> valkyrie: http://drupal.org/node/1428638 for details.                                                                   
==> valkyrie:                                                                                                               
==> valkyrie: Drush was attempting to connect to:                                                                           
==> valkyrie:  Drupal version        :  7.36                                                                                
==> valkyrie:  Site URI              :  valkyrie.local                                                                      
==> valkyrie:  Database driver       :  mysql                                                                               
==> valkyrie:  Database hostname     :  localhost                                                                           
==> valkyrie:  Database port         :  3306                                                                                
==> valkyrie:  Database username     :  valkyrielocal                                                                       
==> valkyrie:  Database name         :  valkyrielocal                                                                       
==> valkyrie:  PHP executable        :  /usr/bin/php                                                                        
==> valkyrie:  PHP configuration     :  /etc/php5/cli/php.ini                                                               
==> valkyrie:  PHP OS                :  Linux                                     
==> valkyrie:  Drush version         :  7.0-dev                                   
==> valkyrie:  Drush temp            :  /tmp                                      
==> valkyrie:  directory                                                          
==> valkyrie:  Drush configuration   :  /var/aegir/hostmaster-7.x-3.x/sites/valky 
==> valkyrie:                           rie.local/drushrc.php                     
==> valkyrie:                           /var/aegir/hostmaster-7.x-3.x/sites/all/d 
==> valkyrie:                           rush/drushrc.php                          
==> valkyrie:                           /var/aegir/.drush/drushrc.php             
==> valkyrie:  Drush alias files     :  /var/aegir/.drush/hostmaster.alias.drushr 
==> valkyrie:                           c.php                                     
==> valkyrie:                           /var/aegir/.drush/server_master.alias.dru 
==> valkyrie:                           shrc.php                                  
==> valkyrie:                           /var/aegir/.drush/platform_hostmaster.ali 
==> valkyrie:                           as.drushrc.php                            
==> valkyrie:                           /var/aegir/.drush/hm.alias.drushrc.php    
==> valkyrie:                           /var/aegir/.drush/server_localhost.alias. 
==> valkyrie:                           drushrc.php                               
==> valkyrie:  Drupal root           :  /var/aegir/hostmaster-7.x-3.x             
==> valkyrie:  Site path             :  sites/valkyrie.local                      
==> valkyrie: 
==> valkyrie: FATAL: all hosts have already failed -- aborting
==> valkyrie: 
==> valkyrie: TASK: [getvalkyrie.valkyrie | Add Skynet Supervisor config] ******************* 
==> valkyrie: changed: [localhost]
==> valkyrie: 
==> valkyrie: FATAL: all hosts have already failed -- aborting
==> valkyrie: 
==> valkyrie: PLAY RECAP ******************************************************************** 
==> valkyrie:            to retry, use: --limit @/root/site.retry
==> valkyrie: localhost                  : ok=72   changed=43   unreachable=0    failed=1   
The SSH command responded with a non-zero exit status. Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.
Enter passphrase for key '/home/valkyrie/.ssh/id_rsa': 
[valkyrie@sz6 ~]$

I use the same drush dev version that was working to create new VMs with 45e0de3.

[ghost]

Updating host's Drush to latest dev version doesn't fix the problem.

[ergonlogic]

What happens if you just run the provisioning again: cd shiftmedia; vagrant provision?

You may also want to run an ssh agent (ssh-add) to avoid password prompts during the install.

Also, the issue appear to be with the DB, so look earlier in the log, to see if anything seems amiss.

Finally, you may want to try the released version on Valkyrie (drush dl valkyrie).

[ghost]

Running vagrant provision was returning an error too (cannot remember which one, I'll retry later). After ssh'ing to the vm, the database server was indeed not running. I haven't the full vnew log anymore, but I'll check next time I'll have to create a new vm.

As a workaround, I changed vagrant/ansible/roles/getvalkyrie.aegir/handlers/main.yml:8 from
shell: drush @hm cc drush && drush @hm hosting-task @hostmaster verify --force
to
shell: drush @hm cc drush

It removes the verify, but the vm creation is ok (it requires a reboot before doing anything in order to start MySQL however).

[ergonlogic]

I cannot reproduce this. drush vnew works just fine for me on both the latest commit on the 0.4.x branch, and the released version on tag 0.4.1.

[mattcoker]

Spoke with @MatthewHager about this, he seems to think its a race condition. Its inconsistently failing in at least 3 different ways.

==> valkyrie: NOTIFIED: [geerlingguy.php | restart webserver] *******************************
==> valkyrie: changed: [localhost]
==> valkyrie:
==> valkyrie: NOTIFIED: [geerlingguy.php | restart php-fpm] *********************************
==> valkyrie: skipping: [localhost]
==> valkyrie:
==> valkyrie: NOTIFIED: [geerlingguy.mysql | restart mysql] *********************************
==> valkyrie: changed: [localhost]
==> valkyrie:
==> valkyrie: NOTIFIED: [getvalkyrie.aegir | Verify Aegir front-end] ************************
==> valkyrie: failed: [localhost] => {"changed": true, "cmd": "drush @hm cc drush && drush @hm hosting-task @hostmaster verify --force", "delta": "0:00:05.672874", "end": "2015-04-06 16:27:13.347065", "rc": 1, "start": "2015-04-06 16:27:07.674191", "warnings": []}
==> valkyrie: stderr: 'drush' cache was cleared.                                             [success]
==> valkyrie: The drush command 'hosting-task @hostmaster verify' could not be         [error]
==> valkyrie: found.  Run `drush cache-clear drush` to clear the commandfile cache
==> valkyrie: if you have installed new extensions.
==> valkyrie: Drush was not able to start (bootstrap) the Drupal database.             [error]
==> valkyrie: Hint: This may occur when Drush is trying to:
==> valkyrie:  * bootstrap a site that has not been installed or does not have a
==> valkyrie: configured database. In this case you can select another site with a
==> valkyrie: working database setup by specifying the URI to use with the --uri
==> valkyrie: parameter on the command line. See `drush topic docs-aliases` for
==> valkyrie: details.
==> valkyrie:  * connect the database through a socket. The socket file may be
==> valkyrie: wrong or the php-cli may have no access to it in a jailed shell. See
==> valkyrie: http://drupal.org/node/1428638 for details.
==> valkyrie:
==> valkyrie: Drush was attempting to connect to:
==> valkyrie:  Drupal version        :  7.36
==> valkyrie:  Site URI              :  valkyrie.val
==> valkyrie:  Database driver       :  mysql
==> valkyrie:  Database hostname     :  localhost
==> valkyrie:  Database port         :  3306
==> valkyrie:  Database username     :  valkyrieval
==> valkyrie:  Database name         :  valkyrieval
==> valkyrie:  PHP executable        :  /usr/bin/php
==> valkyrie:  PHP configuration     :  /etc/php5/cli/php.ini
==> valkyrie:  PHP OS                :  Linux
==> valkyrie:  Drush version         :  7.0-dev
==> valkyrie:  Drush temp            :  /tmp
==> valkyrie:  directory
==> valkyrie:  Drush configuration   :  /var/aegir/hostmaster-7.x-3.x/sites/valky
==> valkyrie:                           rie.val/drushrc.php
==> valkyrie:                           /var/aegir/hostmaster-7.x-3.x/sites/all/d
==> valkyrie:                           rush/drushrc.php
==> valkyrie:                           /var/aegir/.drush/drushrc.php
==> valkyrie:  Drush alias files     :  /var/aegir/.drush/server_localhost.alias.
==> valkyrie:                           drushrc.php
==> valkyrie:                           /var/aegir/.drush/hostmaster.alias.drushr
==> valkyrie:                           c.php
==> valkyrie:                           /var/aegir/.drush/server_master.alias.dru
==> valkyrie:                           shrc.php
==> valkyrie:                           /var/aegir/.drush/hm.alias.drushrc.php
==> valkyrie:                           /var/aegir/.drush/platform_hostmaster.ali
==> valkyrie:                           as.drushrc.php
==> valkyrie:  Drupal root           :  /var/aegir/hostmaster-7.x-3.x
==> valkyrie:  Site path             :  sites/valkyrie.val
==> valkyrie:
==> valkyrie: FATAL: all hosts have already failed -- aborting
==> valkyrie:
==> valkyrie: TASK: [getvalkyrie.valkyrie | Add Skynet Supervisor config] *******************
==> valkyrie: changed: [localhost]
==> valkyrie:
==> valkyrie: FATAL: all hosts have already failed -- aborting
==> valkyrie:
==> valkyrie: PLAY RECAP ********************************************************************
==> valkyrie:            to retry, use: --limit @/root/site.retry
==> valkyrie:
==> valkyrie: localhost                  : ok=72   changed=43   unreachable=0    failed=1
The SSH command responded with a non-zero exit status. Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.
The external command could not be executed due to an application error.                                                                                      [error]
Illegal string offset 'site' backend.inc:1030                                                                                                                [warning]
        [error]ld not be executed successfully (returned: ssh: Could not resolve hostname valkyrie.val: nodename nor servname provided, or not known
, code: 255)
➜  Development

[mattcoker]

Here is an error from another attempt.

==> valkyrie: NOTIFIED: [geerlingguy.php | restart webserver] *******************************
==> valkyrie: changed: [localhost]
==> valkyrie:
==> valkyrie: NOTIFIED: [geerlingguy.php | restart php-fpm] *********************************
==> valkyrie: skipping: [localhost]


==> valkyrie:
==> valkyrie: NOTIFIED: [geerlingguy.mysql | restart mysql] *********************************
==> valkyrie: failed: [localhost] => {"failed": true}
==> valkyrie: msg:  * Stopping MySQL database server mysqld
==> valkyrie:    ...done.
==> valkyrie:  * Starting MySQL database server mysqld
==> valkyrie:    ...fail!
==> valkyrie:
==> valkyrie:
==> valkyrie: FATAL: all hosts have already failed -- aborting
==> valkyrie:
==> valkyrie: TASK: [getvalkyrie.valkyrie | Add Skynet Supervisor config] *******************
==> valkyrie: changed: [localhost]
==> valkyrie:
==> valkyrie: FATAL: all hosts have already failed -- aborting
==> valkyrie:
==> valkyrie: PLAY RECAP ********************************************************************
==> valkyrie:            to retry, use: --limit @/root/site.retry
==> valkyrie:
==> valkyrie: localhost                  : ok=71   changed=42   unreachable=0    failed=1
The SSH command responded with a non-zero exit status. Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.

[mattcoker]

The above errors were after cleaning out my .drushrc.php file and deleting the known_hosts file. Errors are on a Mac running 10.10.2. @Peuc did you have this issue on a mac?

[MatthewHager]

To deepen the plot, I just tried on a freshly formatted mac and it worked perfectly.

[ergonlogic]

Can you investigate why MySQL is failing to start/re-start? That appears to be at the root of this. Take a look in the log on the VM (/var/log/mysql.err, iirc)

[ghost]

I agree with the race condition explanation, because I also have the MySQL install step which sometimes fails silently (the install process just freezes and nothing happens anymore no matter how long you wait).

I've not reported it so far because I have no details, but I will check in the logs what happens next time it will occur.

[ghost]

I just deployed a new VM, same problem. Here is the content of /var/log/mysqld.log:

150409 13:36:43 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
150409 13:36:44 [Warning] 'THREAD_CONCURRENCY' is deprecated and will be removed in a future release.
150409 13:36:44 [Note] Plugin 'FEDERATED' is disabled.
150409 13:36:44 InnoDB: The InnoDB memory heap is disabled
150409 13:36:44 InnoDB: Mutexes and rw_locks use GCC atomic builtins
150409 13:36:44 InnoDB: Compressed tables use zlib 1.2.8
150409 13:36:44 InnoDB: Using Linux native AIO
150409 13:36:44 InnoDB: Initializing buffer pool, size = 256.0M
150409 13:36:44 InnoDB: Completed initialization of buffer pool
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
150409 13:36:44  InnoDB: Retrying to lock the first data file
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
150409 13:38:25  InnoDB: Unable to open the first data file
InnoDB: Error in opening ./ibdata1
150409 13:38:25  InnoDB: Operating system error number 11 in a file operation.
InnoDB: Error number 11 means 'Resource temporarily unavailable'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.5/en/operating-system-error-codes.html
150409 13:38:25 InnoDB: Could not open or create data files.
150409 13:38:25 InnoDB: If you tried to add new data files, and it failed here,
150409 13:38:25 InnoDB: you should now edit innodb_data_file_path in my.cnf back
150409 13:38:25 InnoDB: to what it was, and remove the new ibdata files InnoDB created
150409 13:38:25 InnoDB: in this failed attempt. InnoDB only wrote those files full of
150409 13:38:25 InnoDB: zeros, but did not yet use them in any way. But be careful: do not
150409 13:38:25 InnoDB: remove old data files which contain your precious data!
150409 13:38:25 [ERROR] Plugin 'InnoDB' init function returned error.
150409 13:38:25 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
150409 13:38:25 [ERROR] Unknown/unsupported storage engine: InnoDB
150409 13:38:25 [ERROR] Aborting

150409 13:38:25 [Note] /usr/sbin/mysqld: Shutdown complete

150409 13:38:25 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

[mattcoker]

I want to provide some additional information.

I ran a vnew on a brand new machine, never ran a vnew on it before. It worked fine. @Peuc , have you ever manually deleted the virtual machine rather than run a vagrant destroy? I had been doing that because of a bug when trying to run vagrant destroy a couple of months back. I can't help but wonder if that has left something behind that causes this problem.

[ghost]

@mattcoker: Sorry, I didn't notice your question earlier. I tested with a Linux host only, I have no OSX system to do more tests.

Also, I usually remove VMs manually:

• Delete the VM files through the Virtualbox UI
• rm -rf the VM's Vagrant directory
• Remove reference to the VM in known_hosts
• Remove obsolete entries in /etc/exports

[mattcoker]

@Peuc what you just described is exactly what I did. Originally I was doing steps 1 and 2, then @MatthewHager showed me steps 3 and 4.

[ergonlogic]

vagrant destroy isn't working for you? There are hooks in there to clean up things like alias file search paths, NFS exports, and such. It's definitely preferred over manually deleting these files.

[ergonlogic]

FYI, I've finally seen something along these lines. I'm investigating and posted: geerlingguy/ansible-role-mysql#33

[ergonlogic]

I forked @geerlingguy's mysql role, and added a 5 second sleep to the service restart handler. Since I've only seen this behaviour the once, I can't really tell whether this has worked.

@Peuc @mattcoker: Could you guys test building a new project, and see if this helps resolve the issue?

[ergonlogic]

FYI, to test this, you needn't do anything with your working Valkyrie install(s), except halt the VM(s). You'll then want to ensure that the Ansible role submodules are updated with git pull && git submodule update --init --recursive (in ~/.drush/valkyrie). Then run a new drush vnew.

[ghost]

I can confirm it works. In previous version, every vnew was failing but I just successfully deployed two new VMs with the new one with success.

Here is the vnew log:

[…]
==> valkyrie: TASK: [geerlingguy.mysql | Ensure MySQL packages are installed.] ************** 
==> valkyrie: changed: [localhost] => (item=mysql-common,mysql-server,python-mysqldb)
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Ensure MySQL is stopped after initial install.] **** 
==> valkyrie: changed: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Delete innodb log files created by apt package after initial install.] *** 
==> valkyrie: changed: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Copy my.cnf global MySQL configuration.] *********** 
==> valkyrie: changed: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Ensure MySQL is started and enabled on boot.] ****** 
==> valkyrie: ok: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Get list of hosts for the root user.] ************** 
==> valkyrie: ok: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Update MySQL root password for localhost root account.] *** 
==> valkyrie: changed: [localhost] => (item=valkyrie)
==> valkyrie: changed: [localhost] => (item=127.0.0.1)
==> valkyrie: changed: [localhost] => (item=::1)
==> valkyrie: changed: [localhost] => (item=localhost)
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Copy .my.cnf file with root password credentials.] *** 
==> valkyrie: changed: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Get list of hosts for the anonymous user.] ********* 
==> valkyrie: ok: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Remove anonymous MySQL users.] ********************* 
==> valkyrie: skipping: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Remove MySQL test database.] *********************** 
==> valkyrie: ok: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Ensure MySQL databases are present.] *************** 
==> valkyrie: skipping: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Ensure MySQL users are present.] ******************* 
==> valkyrie: skipping: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Ensure replication user exists on master.] ********* 
==> valkyrie: skipping: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Check slave replication status.] ******************* 
==> valkyrie: skipping: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Check master replication status.] ****************** 
==> valkyrie: skipping: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Configure replication on the slave.] *************** 
==> valkyrie: skipping: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [geerlingguy.mysql | Start replication.] ******************************** 
==> valkyrie: skipping: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [getvalkyrie.aegir | Ensure Aegir's dependencies are installed.] ******** 
==> valkyrie: changed: [localhost] => (item=apache2,php5,php5-cli,php5-gd,php5-mysql,postfix,sudo,rsync,git,unzip)
[…]
==> valkyrie: NOTIFIED: [geerlingguy.php | restart webserver] ******************************* 
==> valkyrie: changed: [localhost]
==> valkyrie: 
==> valkyrie: NOTIFIED: [geerlingguy.php | restart php-fpm] ********************************* 
==> valkyrie: skipping: [localhost]
==> valkyrie: 
==> valkyrie: NOTIFIED: [geerlingguy.mysql | restart mysql] ********************************* 
==> valkyrie: changed: [localhost]
==> valkyrie: 
==> valkyrie: NOTIFIED: [getvalkyrie.aegir | Verify Aegir front-end] ************************ 
==> valkyrie: changed: [localhost]
==> valkyrie: 
==> valkyrie: 
==> valkyrie: TASK: [getvalkyrie.skynet | Add Skynet Supervisor config] ********************* 
==> valkyrie: changed: [localhost]
==> valkyrie: 
==> valkyrie: TASK: [getvalkyrie.skynet | Start Skynet via Supervisor] ********************** 
==> valkyrie: ok: [localhost]
[…]

After successful vnew, the /var/log/mysqld.log doesn't exists.

[ergonlogic]

Great! I'm going to close this issue then. Feel free to re-open if this begins to recur.