Execution Expired when Creating Host

Problem: When running hammer host create, I am seeing the following output:
Could not create the host:
execution expired

Foreman and Proxy versions:
foreman-1.22.0-1.el7.noarch
foreman-proxy-1.22.0-1.el7.noarch

Other relevant data:
Some internet searches have suggested there might be a problem with DNS, but the hostname and IP we are using have been verified to resolve correctly on our Foreman host.

We are seeing the following in /var/log/foreman/production.log:

2019-08-12T12:52:06 [I|app|897b5417] Authorized user admin(Admin User)
2019-08-12T12:52:06 [I|app|897b5417] Current user set to admin (admin)
2019-08-12T12:52:10 [W|app|897b5417] Action failed
Net::Error: execution expired
/usr/share/foreman/lib/net/dns.rb:62:in `rescue in lookup'
/usr/share/foreman/lib/net/dns.rb:19:in `lookup'
/usr/share/foreman/lib/net/dns.rb:87:in `dns_lookup'
/usr/share/foreman/lib/net/dns/forward_record.rb:22:in `conflicts'
/usr/share/foreman/lib/net.rb:23:in `conflicting?'
/usr/share/foreman/app/models/concerns/orchestration/dns.rb:99:in `block in queue_remove_dns_co
nflicts'
/usr/share/foreman/app/models/concerns/orchestration/dns.rb:98:in `each'
/usr/share/foreman/app/models/concerns/orchestration/dns.rb:98:in `queue_remove_dns_conflicts'
/usr/share/foreman/app/models/concerns/orchestration/dns.rb:59:in `queue_dns'

The actual work for DNS is done by the Smart Proxy with the DNS feature for the assigned Subnet. Can you look into and provide the corresponding Smart Proxy logs (/var/log/foreman-proxy/proxy.log)? This should provide more details about the failure.

The problem is that Foreman core application performs DNS query to check if the new/changed DNS entry already exists. It does that via OS-level DNS resolver (/etc/resolv.conf) and if you misconfigured that you can run into timeouts.

Foreman also performs DNS lookups aganst Subnet DNS smart proxy in some cases, but in this case (and the stacktrace confirms) it’s the OS resolver which timeouts.

We are improving this code for 1.24 so it’s more configurable with multiple DNS query attempts, today it’s just a single DNS query and a single timeout (which is configurable tho).

Hi All,

This is from the proxy.log:

2019-08-13T07:54:44 3d71d88f [I] Started GET /serverName
2019-08-13T07:54:44 3d71d88f [I] Finished GET /serverName with 200 (0.31 ms)
2019-08-13T07:54:44 3d71d88f [I] Started GET /172.x.0.0/mac/
2019-08-13T07:54:44 3d71d88f [E] No DHCP record for MAC 172.x.0.0/ found
2019-08-13T07:54:44 3d71d88f [I] Finished GET /172.x.0.0/mac/ with 404 (0.45 ms)
2019-08-13T07:54:44 3d71d88f [I] Started GET /172.x.0.0/ip/172.x.x.x
2019-08-13T07:54:44 3d71d88f [E] No DHCP records for IP 172.x.0.0/172.x.x.x found
2019-08-13T07:54:44 3d71d88f [I] Finished GET /172.x.0.0/ip/172.x.x.x with 404 (0.41 ms)
2019-08-13T07:54:44 3d71d88f [I] Started GET /172.x.0.0/mac/
2019-08-13T07:54:44 3d71d88f [E] No DHCP record for MAC 172.x.0.0/ found
2019-08-13T07:54:44 3d71d88f [I] Finished GET /172.x.0.0/mac/ with 404 (0.45 ms)
2019-08-13T07:54:44 3d71d88f [I] Started GET /172.x.0.0/ip/172.x.x.x
2019-08-13T07:54:44 3d71d88f [E] No DHCP records for IP 172.x.0.0/172.x.x.x found
2019-08-13T07:54:44 3d71d88f [I] Finished GET /172.x.0.0/ip/172.x.x.x with 404 (0.4 ms)

If I’m on the foreman server, I can nslookup both forward and reverse without issues. They return almost immediately (.015s).

Any other ideas or how to get more debugging to help figure out what’s going on?

Thanks,
-Jay

Hi,

If I manually add the host via the web forms, it works, this is all from the CLI. here is the hammer command output with debug:

[ INFO 2019-08-13T08:26:50 API] Server: https://foreman-server
[ INFO 2019-08-13T08:26:50 API] POST /api/hosts
[DEBUG 2019-08-13T08:26:50 API] Params: {
“location_id” => 1,
“organization_id” => 2,
“host” => {
“name” => “nodename”,
“location_id” => 1,
“organization_id” => 2,
“puppetclass_ids” => ,
“hostgroup_id” => 1,
“build” => false,
“compute_attributes” => {
“volumes_attributes” => {}
},
“managed” => true,
“enabled” => true,
“overwrite” => true,
“interfaces_attributes” => [
[0] {
“type” => “interface”,
“mac” => “macaddress”,
“ip” => “ipaddress”,
“name” => “nodename”,
“managed” => “true”,
“primary” => “true”,
“provision” => “true”
},
[1] {
“type” => “bmc”,
“mac” => “macaddress”,
“ip” => “ipaddress”,
“name” => “nodename-ipmi”,
“domain_id” => “2”,
“subnet_id” => “1”,
“managed” => “true”,
“username” => “ADMIN”,
“password” => “***”,
“provider” => “IPMI”
}
]
}
}
[DEBUG 2019-08-13T08:26:50 API] Headers: {}
[DEBUG 2019-08-13T08:26:50 API] Using authenticator: HammerCLIForeman::Api::InteractiveBasicAuth
[ERROR 2019-08-13T08:26:54 API] 500 Internal Server Error
[DEBUG 2019-08-13T08:26:54 API] {
“error” => {
“message” => “execution expired”
}
}
[DEBUG 2019-08-13T08:26:54 Exception] Using exception handler HammerCLIForeman::ExceptionHandler#handle_internal_error
[ERROR 2019-08-13T08:26:54 Exception] execution expired
Could not create the host:
execution expired
[ERROR 2019-08-13T08:26:54 Exception]

RestClient::InternalServerError (500 Internal Server Error):
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/abstract_response.rb:223:in exception_with_response' /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/abstract_response.rb:103:inreturn!’
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-bindings-0.2.3/lib/apipie_bindings/api.rb:353:in block in rest_client_call_block' /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/request.rb:807:inprocess_result’
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/request.rb:725:in block in transmit' /opt/rh/rh-ruby25/root/usr/share/ruby/net/http.rb:910:instart’
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/request.rb:715:in transmit' /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/request.rb:145:inexecute’
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/request.rb:52:in execute' /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/resource.rb:67:inpost’
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-bindings-0.2.3/lib/apipie_bindings/api.rb:327:in call_client' /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-bindings-0.2.3/lib/apipie_bindings/api.rb:240:inhttp_call’
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-bindings-0.2.3/lib/apipie_bindings/api.rb:190:in call_action' /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-bindings-0.2.3/lib/apipie_bindings/api.rb:185:incall’
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-bindings-0.2.3/lib/apipie_bindings/resource.rb:21:in call' /opt/theforeman/tfm/root/usr/share/gems/gems/hammer_cli-0.17.1/lib/hammer_cli/apipie/command.rb:53:insend_request’
/opt/theforeman/tfm/root/usr/share/gems/gems/hammer_cli_foreman-0.17.0/lib/hammer_cli_foreman/commands.rb:168:in send_request' /opt/theforeman/tfm/root/usr/share/gems/gems/hammer_cli-0.17.1/lib/hammer_cli/apipie/command.rb:34:inexecute’
/opt/theforeman/tfm/root/usr/share/gems/gems/clamp-1.1.2/lib/clamp/command.rb:63:in run' /opt/theforeman/tfm/root/usr/share/gems/gems/hammer_cli-0.17.1/lib/hammer_cli/abstract.rb:69:inrun’
/opt/theforeman/tfm/root/usr/share/gems/gems/clamp-1.1.2/lib/clamp/subcommand/execution.rb:11:in execute' /opt/theforeman/tfm/root/usr/share/gems/gems/clamp-1.1.2/lib/clamp/command.rb:63:inrun’
/opt/theforeman/tfm/root/usr/share/gems/gems/hammer_cli-0.17.1/lib/hammer_cli/abstract.rb:69:in run' /opt/theforeman/tfm/root/usr/share/gems/gems/clamp-1.1.2/lib/clamp/subcommand/execution.rb:11:inexecute’
/opt/theforeman/tfm/root/usr/share/gems/gems/clamp-1.1.2/lib/clamp/command.rb:63:in run' /opt/theforeman/tfm/root/usr/share/gems/gems/hammer_cli-0.17.1/lib/hammer_cli/abstract.rb:69:inrun’
/opt/theforeman/tfm/root/usr/share/gems/gems/clamp-1.1.2/lib/clamp/command.rb:132:in run' /opt/theforeman/tfm/root/usr/share/gems/gems/hammer_cli-0.17.1/bin/hammer:147:in<top (required)>’
/usr/bin/hammer:23:in load' /usr/bin/hammer:23:in

Hi,

If we disable the DNS proxy for the domain everything works.

-Jay

I know this is confusing, let me explain and put this into our docs.

During DNS record creation, Foreman performs conflict DNS lookups to verify that hostname is not in active use. This check will be performed against one of the following DNS servers:

  • system-wide resolver if Adminster - Setting - query_local_nameservers is set or
  • nameserver(s) defined in the Subnet associated with the Host or
  • authoritative NS queried from SOA from the Domain name associated with the Host

When experiencing timeouts during DNS conflict resolutions, check the following:

  • Subnet nameservers must be reachable from the Foreman server
  • Domain name must have a SOA record available from the Foreman server
  • System resolver (/etc/resolv.conf) must have valid and working configuration