log writing failed. can't be called from trap context

[mkb]

I frequently see the message log writing failed. can't be called from trap context when invoking bosh-bootstrap. Typically I notice it when something fails but I have also seen the message when my command executes successfully.

One example:

      Started deploy micro bosh
      Started deploy micro bosh > Unpacking stemcell. Done (00:00:02)
      Started deploy micro bosh > Uploading stemcelllog writing failed. can't be called from trap context
    create stemcell failed: Timed out reading instance metadata, please make sure CPI is running on EC2 instance:
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_aws_cpi-1.2798.0/lib/cloud/aws/helpers.rb:14:in `cloud_error'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_aws_cpi-1.2798.0/lib/cloud/aws/cloud.rb:65:in `rescue in current_vm_id'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_aws_cpi-1.2798.0/lib/cloud/aws/cloud.rb:46:in `current_vm_id'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_aws_cpi-1.2798.0/lib/cloud/aws/cloud.rb:422:in `block in create_stemcell'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_common-1.2798.0/lib/common/thread_formatter.rb:49:in `with_thread_name'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_aws_cpi-1.2798.0/lib/cloud/aws/cloud.rb:410:in `create_stemcell'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:228:in `block (2 levels) in create_stemcell'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:85:in `step'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:227:in `block in create_stemcell'
    /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/tmpdir.rb:88:in `mktmpdir'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:213:in `create_stemcell'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:118:in `create'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:98:in `block in create_deployment'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:92:in `with_lifecycle'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:98:in `create_deployment'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/cli/commands/micro.rb:179:in `perform'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli-1.2798.0/lib/cli/command_handler.rb:57:in `run'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli-1.2798.0/lib/cli/runner.rb:56:in `run'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli-1.2798.0/lib/cli/runner.rb:16:in `run'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli-1.2798.0/bin/bosh:7:in `<top (required)>'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/bosh:23:in `load'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/bosh:23:in `<main>'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/ruby_executable_hooks:15:in `eval'
    /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/ruby_executable_hooks:15:in `<main>'
    /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/rake/file_utils.rb:54:in `block in create_shell_runner': Command failed with status (1): [bosh -n micro deploy --update-if-exists /U...] (RuntimeError)
            from /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/rake/file_utils.rb:45:in `call'
            from /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/rake/file_utils.rb:45:in `sh'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/cli/helpers/bundle.rb:18:in `block in run'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@global/gems/bundler-1.7.6/lib/bundler.rb:236:in `block in with_clean_env'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@global/gems/bundler-1.7.6/lib/bundler.rb:223:in `with_original_env'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@global/gems/bundler-1.7.6/lib/bundler.rb:229:in `with_clean_env'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/cli/helpers/bundle.rb:16:in `run'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/microbosh.rb:54:in `block in deploy_or_update'
            from /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/fileutils.rb:125:in `chdir'
            from /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/fileutils.rb:125:in `cd'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/microbosh.rb:52:in `deploy_or_update'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/microbosh.rb:42:in `block in deploy'
            from /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/fileutils.rb:125:in `chdir'
            from /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/fileutils.rb:125:in `cd'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/microbosh.rb:40:in `deploy'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/cli/commands/deploy.rb:77:in `perform_microbosh_deploy'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/cli/commands/deploy.rb:24:in `perform'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/thor_cli.rb:11:in `deploy'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/thor-0.19.1/lib/thor/command.rb:27:in `run'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/thor-0.19.1/lib/thor/invocation.rb:126:in `invoke_command'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/thor-0.19.1/lib/thor.rb:359:in `dispatch'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/thor-0.19.1/lib/thor/base.rb:440:in `start'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/bin/bosh-bootstrap:13:in `<top (required)>'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/bosh-bootstrap:23:in `load'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/bosh-bootstrap:23:in `<main>'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/ruby_executable_hooks:15:in `eval'
            from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/ruby_executable_hooks:15:in `<main>'

    mkb@beemo

[drnic]

Would love a fix for this annoyance, yeah.

On Fri, Jan 9, 2015 at 3:11 PM, mkb notifications@github.com wrote:

I frequently see the message log writing failed. can't be called from trap context when invoking bosh-bootstrap. Typically I notice it when something fails but I have also seen the message when my command executes successfully.

One example:

Started deploy micro bosh Started deploy micro bosh > Unpacking stemcell. Done (00:00:02) Started deploy micro bosh > Uploading stemcelllog writing failed. can't be called from trap context create stemcell failed: Timed out reading instance metadata, please make sure CPI is running on EC2 instance: /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_aws_cpi-1.2798.0/lib/cloud/aws/helpers.rb:14:in cloud_error' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh_aws_cpi-1.2798.0/lib/cloud/aws/cloud.rb:65:inrescue in current_vm_id' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_aws_cpi-1.2798.0/lib/cloud/aws/cloud.rb:46:in current_vm_id' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh_aws_cpi-1.2798.0/lib/cloud/aws/cloud.rb:422:inblock in create_stemcell' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_common-1.2798.0/lib/common/thread_formatter.rb:49:in with_thread_name' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh_aws_cpi-1.2798.0/lib/cloud/aws/cloud.rb:410:increate_stemcell' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:228:in block (2 levels) in create_stemcell' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:85:in step' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:227:in block in create_stemcell' /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/tmpdir.rb:88:inmktmpdir' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:213:in create_stemcell' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:118:in create' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:98:in block in create_deployment' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:92:in with_lifecycle' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/deployer/instance_manager.rb:98:in create_deployment' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh_cli_plugin_micro-1.2798.0/lib/bosh/cli/commands/micro.rb:179:in perform' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli-1.2798.0/lib/cli/command_handler.rb:57:in run' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh_cli-1.2798.0/lib/cli/runner.rb:56:inrun' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli-1.2798.0/lib/cli/runner.rb:16:in run' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh_cli-1.2798.0/bin/bosh:7:in' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/bosh:23:in load' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/bosh:23:in' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/ruby_executable_hooks:15:in eval' /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/ruby_executable_hooks:15:in' /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/rake/file_utils.rb:54:in block in create_shell_runner': Command failed with status (1): bosh -n micro deploy --update-if-exists /U... from /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/rake/file_utils.rb:45:in call' from /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/rake/file_utils.rb:45:in sh' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/cli/helpers/bundle.rb:18:inblock in run' from /Users/mkb/.rvm/gems/ruby-2.1.5@global/gems/bundler-1.7.6/lib/bundler.rb:236:in block in with_clean_env' from /Users/mkb/.rvm/gems/ruby-2.1.5@global /gems/bundler-1.7.6/lib/bundler.rb:223:inwith_original_env' from /Users/mkb/.rvm/gems/ruby-2.1.5@global/gems/bundler-1.7.6/lib/bundler.rb:229:in with_clean_env' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/cli/helpers/bundle.rb:16:in run' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/microbosh.rb:54:in block in deploy_or_update' from /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/fileutils.rb:125:in chdir' from /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/fileutils.rb:125:in cd' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/microbosh.rb:52:in deploy_or_update' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/microbosh.rb:42:in block in deploy' from /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/fileutils.rb:125:in chdir' from /Users/mkb/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/fileutils.rb:125:in cd' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/microbosh.rb:40:indeploy' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/cli/commands/deploy.rb:77:in perform_microbosh_deploy' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/cli/commands/deploy.rb:24:in perform' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/bosh-bootstrap-0.15.0/lib/bosh-bootstrap/thor_cli.rb:11:in deploy' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/thor-0.19.1/lib/thor/command.rb:27:inrun' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/thor-0.19.1/lib/thor/invocation.rb:126:in invoke_command' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/thor-0.19.1/lib/thor.rb:359:indispatch' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/gems/thor-0.19.1/lib/thor/base.rb:440:in start' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh /gems/bosh-bootstrap-0.15.0/bin/bosh-bootstrap:13:in' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/bosh-bootstrap:23:in load' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/bosh-bootstrap:23:in' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/ruby_executable_hooks:15:in eval' from /Users/mkb/.rvm/gems/ruby-2.1.5@bosh/bin/ruby_executable_hooks:15:in'

— Reply to this email directly or view it on GitHub https://github.com/cloudfoundry-community/bosh-bootstrap/issues/298.

Dr Nic Williams Stark & Wayne LLC - consultancy for Cloud Foundry users http://drnicwilliams.com http://starkandwayne.com cell +1 (415) 860-2185 twitter @drnic

[mdcarlson]

+1 for a fix

[drnic]

I think this is a bug in"bosh micro deploy" upstream as I saw it the other day without bosh-bootstrap

On Wed, Apr 1, 2015 at 10:36 AM, Mark Carlson notifications@github.com wrote:

+1 for a fix

Reply to this email directly or view it on GitHub: https://github.com/cloudfoundry-community/bosh-bootstrap/issues/298#issuecomment-88568423

[mdcarlson]

I'm hitting it during the terraform-was-cf-install template during the deploy micro bosh step.

aws_instance.bastion (remote-exec):   Started deploy micro bosh > Creating VM from ami-b88da7d0 light
aws_instance.bastion (remote-exec): log writing failed. can't be called from trap context

[drnic]

It is an ignorable warning/error and shouldn't stop anything from working subsequently.

But it's ugly.

On Wed, Apr 1, 2015 at 10:41 AM, Mark Carlson notifications@github.com wrote:

I'm hitting it during the terraform-was-cf-install template during the deploy micro bosh step. aws_instance.bastion (remote-exec): Started deploy micro bosh > Creating VM from ami-b88da7d0 light

aws_instance.bastion (remote-exec): log writing failed. can't be called from trap context

Reply to this email directly or view it on GitHub: https://github.com/cloudfoundry-community/bosh-bootstrap/issues/298#issuecomment-88570540

[mdcarlson]

Ah, good to know. I do see that the real error is an "Address in use" issue. I'll chase that separately.

[drnic]

Created upstream ticket