Project

General

Profile

Feature #12133

Optionally log output of finish scripts (Image Provisioning)

Added by Tommy McNeely almost 4 years ago. Updated over 3 years ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
Unattended installations
Target version:
-
Difficulty:
Triaged:
No
Bugzilla link:
Pull request:
Team Backlog:
Fixed in Releases:
Found in Releases:

Description

When a finish script fails/doesn't run/appears to hang, it would be really nice to be able to see the output of that job. At a minimum, logging to something like /root/foreman-finish-output.txt (or maybe something under /var/log?). Perhaps it could be implemented as a checkbox or something? Then when the script runs, tee its output to the file.

Ideally, I could see the output as some property of the host in the WebUI, so that I wouldn't have to go in and extract the SSH key and login to the system directly. When I see output in the logs like:

```
Started GET "/tasks/6f952f72-c382-4d61-917a-2b3c2f939784" for 50.170.194.170 at 2015-10-11 16:15:44 -0400
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] Processing by TasksController#show as */*
2015-10-11 16:15:44 [I] Parameters: {"id"=>"6f952f72-c382-4d61-917a-2b3c2f939784"}
2015-10-11 16:15:44 [I] Rendered tasks/_list.html.erb (0.7ms)
2015-10-11 16:15:44 [I] Completed 200 OK in 10ms (Views: 1.4ms | ActiveRecord: 1.6ms)
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:44 [I] channel_data: 0 82b
2015-10-11 16:15:45 [I] channel_data: 0 4095b
2015-10-11 16:15:45 [I] channel_data: 0 2110b
2015-10-11 16:15:46 [I] channel_data: 0 191b
2015-10-11 16:15:46 [I] channel_data: 0 32b
2015-10-11 16:15:46 [I]
```

It makes me think that the output of the ssh script is being received by foreman itself, so it really should just be a matter of allowing it to be logged or even better, stored somewhere.

History

#1 Updated by Dominic Cleal almost 4 years ago

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.

#2 Updated by Tommy McNeely almost 4 years ago

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

#3 Updated by Dan Dunckel over 3 years ago

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

#4 Updated by Dominic Cleal over 3 years ago

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.

#5 Updated by Dan Dunckel over 3 years ago

Thanks Dominic! I'll do that.

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

#6 Updated by Dominic Cleal over 3 years ago

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.

#7 Updated by Tommy McNeely over 3 years ago

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

#8 Updated by Dominic Cleal over 3 years ago

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.

Also available in: Atom PDF