why is chef recipe run twice?

Question

I have a very basic recipe right now.

include_recipe 'apache2'

Chef::Log.info(node[:inewebapp][:apache]);
node[:inewebapp][:apache].each do |vhost|
  Chef::Log.info("Currently on host #{vhost['docroot_dir']}");
end

I'm trying to figure out - while building this with test kitchen - do I get log messages like my recipe is being run multiple times?

This is the output of kitchen converge server

   Installing Cookbook Gems:
   Compiling Cookbooks...
   /tmp/kitchen/cache/cookbooks/hostsfile/resources/entry.rb:35: warning: constant ::Fixnum is deprecated
   [2017-07-19T15:36:05+00:00] INFO: [{"docroot_dir"=>"/var/www/host1", "server_name"=>"host1"}, {"docroot_dir"=>"/var/www/host2", "server_name"=>"host2"}]
   [2017-07-19T15:36:05+00:00] INFO: [{"docroot_dir"=>"/var/www/host1", "server_name"=>"host1"}, {"docroot_dir"=>"/var/www/host2", "server_name"=>"host2"}]
   [2017-07-19T15:36:05+00:00] INFO: Currently on host /var/www/host1
   [2017-07-19T15:36:05+00:00] INFO: Currently on host /var/www/host1
   [2017-07-19T15:36:05+00:00] INFO: Currently on host /var/www/host2
   [2017-07-19T15:36:05+00:00] INFO: Currently on host /var/www/host2

I have no attributes/default.rb file is empty and my .kitchen.yml looks like this

  ---
  driver:
    name: vagrant

  provisioner:
    name: chef_zero
    product_name: chef
    product_version: 13.0.118
    log_level: info

  verifier:
    name: inspec

  platforms:
    - name: ubuntu-16.04

  suites:
    - name: server
      run_list:
        - recipe[apt]
        - recipe[ine-webapp::apache]
      verifier:
        inspec_tests:
          - test/integration/server
      attributes:
        inewebapp:
          user: 'vagrant'
          apache:
            - docroot_dir: /var/www/host1
              server_name: host1
            - docroot_dir: /var/www/host2
              server_name: host2

I know my recipes should be idempotent, but I'm not sure why my recipe is being executed twice?

Update

After more carefully examining the output of my kitchen converge server it looks like multiple instances of the chef-client are being run? still not understanding why though?

       Transferring files to <server-ubuntu-1604>
   [2017-07-19T15:58:59+00:00] INFO: Started chef-zero at chefzero://localhost:8889 with repository at /tmp/kitchen, /tmp/kitchen
     One version per cookbook

   [2017-07-19T15:58:59+00:00] INFO: Started chef-zero at chefzero://localhost:8889 with repository at /tmp/kitchen, /tmp/kitchen
     One version per cookbook

   [2017-07-19T15:58:59+00:00] INFO: Forking chef instance to converge...
   [2017-07-19T15:58:59+00:00] INFO: Forking chef instance to converge...
   Starting Chef Client, version 13.0.118
   [2017-07-19T15:58:59+00:00] INFO: *** Chef 13.0.118 ***
   [2017-07-19T15:58:59+00:00] INFO: *** Chef 13.0.118 ***
   [2017-07-19T15:58:59+00:00] INFO: Platform: x86_64-linux
   [2017-07-19T15:58:59+00:00] INFO: Platform: x86_64-linux
   [2017-07-19T15:58:59+00:00] INFO: Chef-client pid: 14491
   [2017-07-19T15:58:59+00:00] INFO: Chef-client pid: 14491
   [2017-07-19T15:58:59+00:00] INFO: The plugin path /etc/chef/ohai/plugins does not exist. Skipping...
   [2017-07-19T15:58:59+00:00] INFO: The plugin path /etc/chef/ohai/plugins does not exist. Skipping...
   [2017-07-19T15:59:00+00:00] INFO: Setting the run_list to ["recipe[apt]", "recipe[ine-webapp::apache]"] from CLI options
   [2017-07-19T15:59:00+00:00] INFO: Setting the run_list to ["recipe[apt]", "recipe[ine-webapp::apache]"] from CLI options
   [2017-07-19T15:59:00+00:00] INFO: Run List is [recipe[apt], recipe[ine-webapp::apache]]
   [2017-07-19T15:59:00+00:00] INFO: Run List is [recipe[apt], recipe[ine-webapp::apache]]
   [2017-07-19T15:59:00+00:00] INFO: Run List expands to [apt, ine-webapp::apache]
   [2017-07-19T15:59:00+00:00] INFO: Run List expands to [apt, ine-webapp::apache]
   [2017-07-19T15:59:00+00:00] INFO: Starting Chef Run for server-ubuntu-1604
   [2017-07-19T15:59:00+00:00] INFO: Starting Chef Run for server-ubuntu-1604
   [2017-07-19T15:59:00+00:00] INFO: Running start handlers
   [2017-07-19T15:59:00+00:00] INFO: Running start handlers
   [2017-07-19T15:59:00+00:00] INFO: Start handlers complete.
   [2017-07-19T15:59:00+00:00] INFO: Start handlers complete.
   resolving cookbooks for run list: ["apt", "ine-webapp::apache"]

There is only one instance in my kitchen list

    chef-repo/cookbooks/ine-webapp$ kitchen list
    Instance            Driver   Provisioner  Verifier  Transport  Last Action  Last Error
    server-ubuntu-1604  Vagrant  ChefZero     Inspec    Ssh        Converged    <None>

Answer 1

We don't know what causes the double logging yet, just that it appears to not be consistent enough to debug :( If you can come up with a minimal repro case, please let us know. Otherwise it seems to just go away sometimes.