It's not as clear as you'd like, but FYI stdout is logged to debug level logs (http://projects.theforeman.org/projects/foreman/wiki/Troubleshooting#How-do-I-enable-debugging) and stderr is logged to warning level. If it hangs, nothing is going to get logged though, since the output appears to be buffered.

Well, I don't feel like its really reasonable to leave the production server in debug mode, there really needs to be a way to do this selectively (maybe a log level override for a host provision operation?). Also, as you have noted, I would consider that a workaround at best. The output should be available to the webUI (maybe a details button) during provisioning, which means it probably needs to be stored somewhere (at least temporarily). If it is stored somewhere, and associated with the host, it would be really useful for trying to figure out what happened on a larger (multi-host) deployment.

I realize this wont be an "easy" feature :)

~tommy

I'm running Foreman v1.10.1.

I recently came across this issue hoping to figure out how I could see the output from SSH provisioning of our physical, ESX hosts. I didn't know it at the time, but our provisioning template was trying and failing to run "esxcli software vib -install" of a number of VIBs.

I set the logging level to debug and reran the build. All I seem to get in /var/log/foreman/production.log are messages like this:

2016-02-19T01:04:17 [app] [I] Started GET "/unattended/finish?hostname=esx-34-dell-c6220.ta.local" for 10.0.24.104 at 2016-02-19 01:04:17 +0000
2016-02-19T01:04:17 [app] [I] Processing by UnattendedController#finish as HTML
2016-02-19T01:04:17 [app] [I]   Parameters: {"hostname"=>"esx-34-dell-c6220.ta.local"}
2016-02-19T01:04:17 [app] [D] Setting current user thread-local variable to admin
2016-02-19T01:04:17 [app] [I] Found esx-34-dell-c6220.ta.local
2016-02-19T01:04:17 [app] [D] rendering DB template VMware vSphere ESXi: Finish - finish
2016-02-19T01:04:17 [app] [I]   Rendered inline template (3.1ms)
2016-02-19T01:04:17 [app] [I] Completed 200 OK in 113.2ms (Views: 4.2ms | ActiveRecord: 14.4ms)

2016-02-19T01:04:18 [app] [I] Started GET "/unattended/provision?hostname=esx-34-dell-c6220.ta.local" for 10.0.24.104 at 2016-02-19 01:04:18 +0000
2016-02-19T01:04:18 [app] [I] Processing by UnattendedController#provision as HTML
2016-02-19T01:04:18 [app] [I]   Parameters: {"hostname"=>"esx-34-dell-c6220.ta.local"}
2016-02-19T01:04:18 [app] [D] Setting current user thread-local variable to admin
2016-02-19T01:04:18 [app] [I] Found esx-34-dell-c6220.ta.local
2016-02-19T01:04:18 [app] [D] rendering DB template VMware vSphere ESXi: Provision - provision
2016-02-19T01:04:18 [app] [D] rendering snippet VMware vSphere ESXi: Provision-ConfigureNetApp
2016-02-19T01:04:18 [app] [D] rendering snippet VMware vSphere ESXi: Provision-Default
2016-02-19T01:04:18 [app] [I]   Rendered inline template (229.3ms)
2016-02-19T01:04:18 [app] [I] Completed 200 OK in 290.2ms (Views: 202.5ms | ActiveRecord: 35.3ms)
2016-02-19T01:04:20 [app] [I] Started GET "/unattended/PXELinux?hostname=esx-34-dell-c6220.ta.local" for 10.0.24.104 at 2016-02-19 01:04:20 +0000
2016-02-19T01:04:20 [app] [I] Processing by UnattendedController#PXELinux as HTML
2016-02-19T01:04:20 [app] [I]   Parameters: {"hostname"=>"esx-34-dell-c6220.ta.local"}
2016-02-19T01:04:20 [app] [D] Setting current user thread-local variable to admin
2016-02-19T01:04:20 [app] [I] Found esx-34-dell-c6220.ta.local
2016-02-19T01:04:20 [app] [D] rendering DB template VMware vSphere ESXi: PXElinux - PXELinux
2016-02-19T01:04:20 [app] [I]   Rendered inline template (277.8ms)
2016-02-19T01:04:20 [app] [I] Completed 200 OK in 298.1ms (Views: 268.1ms | ActiveRecord: 15.9ms)

From my research, I believe this is the code that is executed:
https://github.com/theforeman/foreman/blob/1.10.1/app/services/foreman/provision/ssh.rb#L16

The "@results" array should contain info sent back from "Fog::SSH", and as you said, the "stdout" results are logged to "debug" while "stderr" goes to "warn". I could be wrong, but it seems like the "@results" array is empty or a combo of incorrect configuration and or I'm looking in the wrong place.

Any guidance would be extremely helpful. And please let me know if you'd prefer to have this tracked on an "issue" and not a "feature" request.

Thanks

Dan, your log shows a host that's doing network/PXE provisioning, not image based, so this isn't relevant. There's no mechanism to pick up errors in a finish/provision script, you will need to log it on the host itself.

Thanks Dominic! I'll do that.

Forgive my ignorance, but would it be possible to "pick up errors in a finish/provision script"?

Dan Dunckel wrote:

Forgive my ignorance, but would it be possible to "pick up errors in a finish/provision script"?

Perhaps, with changes to the scripts and ways to notify Foreman on error. This should be filed as a separate feature request though.

Please forgive me if I am stating the obvious here...

The foreman server (or at some point in the future, perhaps a smart proxy) is SSH-ing into the server to run the finish script. All the output is being sent to the foreman server, so it could be "logged" somewhere (optionally, of course).

Now, with "user-data" style provisioning, the "finish script" is dumped off to the provider during provisioning, so there is no interaction. I would suggest that we keep this specific request focused on the "SSH" style provisioning to keep things simple.

tommy

Tommy, you're correct. Dan's case is PXE provisioning (so no SSH), which is more similar to user data. Agreed, keep this ticket to SSH.