1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
|
from fcntl import fcntl, F_GETFL, F_SETFL
from os import O_NONBLOCK, read, path
import subprocess
from select import select
from ceph_volume import terminal
from ceph_volume.util import as_bytes
from ceph_volume.util.system import which, run_host_cmd, host_rootfs
import logging
logger = logging.getLogger(__name__)
def log_output(descriptor, message, terminal_logging, logfile_logging):
"""
log output to both the logger and the terminal if terminal_logging is
enabled
"""
if not message:
return
message = message.strip()
line = '%s %s' % (descriptor, message)
if terminal_logging:
getattr(terminal, descriptor)(message)
if logfile_logging:
logger.info(line)
def log_descriptors(reads, process, terminal_logging):
"""
Helper to send output to the terminal while polling the subprocess
"""
# these fcntl are set to O_NONBLOCK for the filedescriptors coming from
# subprocess so that the logging does not block. Without these a prompt in
# a subprocess output would hang and nothing would get printed. Note how
# these are just set when logging subprocess, not globally.
stdout_flags = fcntl(process.stdout, F_GETFL) # get current p.stdout flags
stderr_flags = fcntl(process.stderr, F_GETFL) # get current p.stderr flags
fcntl(process.stdout, F_SETFL, stdout_flags | O_NONBLOCK)
fcntl(process.stderr, F_SETFL, stderr_flags | O_NONBLOCK)
descriptor_names = {
process.stdout.fileno(): 'stdout',
process.stderr.fileno(): 'stderr'
}
for descriptor in reads:
descriptor_name = descriptor_names[descriptor]
try:
message = read(descriptor, 1024)
if not isinstance(message, str):
message = message.decode('utf-8')
log_output(descriptor_name, message, terminal_logging, True)
except (IOError, OSError):
# nothing else to log
pass
def obfuscate(command_, on=None):
"""
Certain commands that are useful to log might contain information that
should be replaced by '*' like when creating OSDs and the keyrings are
being passed, which should not be logged.
:param on: A string (will match a flag) or an integer (will match an index)
If matching on a flag (when ``on`` is a string) it will obfuscate on the
value for that flag. That is a command like ['ls', '-l', '/'] that calls
`obfuscate(command, on='-l')` will obfustace '/' which is the value for
`-l`.
The reason for `on` to allow either a string or an integer, altering
behavior for both is because it is easier for ``run`` and ``call`` to just
pop a value to obfuscate (vs. allowing an index or a flag)
"""
command = command_[:]
msg = "Running command: %s" % ' '.join(command)
if on in [None, False]:
return msg
if isinstance(on, int):
index = on
else:
try:
index = command.index(on) + 1
except ValueError:
# if the flag just doesn't exist then it doesn't matter just return
# the base msg
return msg
try:
command[index] = '*' * len(command[index])
except IndexError: # the index was completely out of range
return msg
return "Running command: %s" % ' '.join(command)
def run(command, run_on_host=False, **kw):
"""
A real-time-logging implementation of a remote subprocess.Popen call where
a command is just executed on the remote end and no other handling is done.
:param command: The command to pass in to the remote subprocess.Popen as a list
:param stop_on_error: If a nonzero exit status is return, it raises a ``RuntimeError``
:param fail_msg: If a nonzero exit status is returned this message will be included in the log
"""
executable = which(command.pop(0), run_on_host)
command.insert(0, executable)
if run_on_host and path.isdir(host_rootfs):
command = run_host_cmd + command
stop_on_error = kw.pop('stop_on_error', True)
command_msg = obfuscate(command, kw.pop('obfuscate', None))
fail_msg = kw.pop('fail_msg', None)
logger.info(command_msg)
terminal.write(command_msg)
terminal_logging = kw.pop('terminal_logging', True)
process = subprocess.Popen(
command,
stdout=subprocess.PIPE,
stderr=subprocess.PIPE,
close_fds=True,
**kw
)
while True:
reads, _, _ = select(
[process.stdout.fileno(), process.stderr.fileno()],
[], []
)
log_descriptors(reads, process, terminal_logging)
if process.poll() is not None:
# ensure we do not have anything pending in stdout or stderr
log_descriptors(reads, process, terminal_logging)
break
returncode = process.wait()
if returncode != 0:
msg = "command returned non-zero exit status: %s" % returncode
if fail_msg:
logger.warning(fail_msg)
if terminal_logging:
terminal.warning(fail_msg)
if stop_on_error:
raise RuntimeError(msg)
else:
if terminal_logging:
terminal.warning(msg)
logger.warning(msg)
def call(command, run_on_host=False, **kw):
"""
Similar to ``subprocess.Popen`` with the following changes:
* returns stdout, stderr, and exit code (vs. just the exit code)
* logs the full contents of stderr and stdout (separately) to the file log
By default, no terminal output is given, not even the command that is going
to run.
Useful when system calls are needed to act on output, and that same output
shouldn't get displayed on the terminal.
Optionally, the command can be displayed on the terminal and the log file,
and log file output can be turned off. This is useful to prevent sensitive
output going to stderr/stdout and being captured on a log file.
:param terminal_verbose: Log command output to terminal, defaults to False, and
it is forcefully set to True if a return code is non-zero
:param logfile_verbose: Log stderr/stdout output to log file. Defaults to True
:param verbose_on_failure: On a non-zero exit status, it will forcefully set logging ON for
the terminal. Defaults to True
"""
executable = which(command.pop(0), run_on_host)
command.insert(0, executable)
if run_on_host and path.isdir(host_rootfs):
command = run_host_cmd + command
terminal_verbose = kw.pop('terminal_verbose', False)
logfile_verbose = kw.pop('logfile_verbose', True)
verbose_on_failure = kw.pop('verbose_on_failure', True)
show_command = kw.pop('show_command', False)
command_msg = "Running command: %s" % ' '.join(command)
stdin = kw.pop('stdin', None)
logger.info(command_msg)
if show_command:
terminal.write(command_msg)
process = subprocess.Popen(
command,
stdout=subprocess.PIPE,
stderr=subprocess.PIPE,
stdin=subprocess.PIPE,
close_fds=True,
**kw
)
if stdin:
stdout_stream, stderr_stream = process.communicate(as_bytes(stdin))
else:
stdout_stream = process.stdout.read()
stderr_stream = process.stderr.read()
returncode = process.wait()
if not isinstance(stdout_stream, str):
stdout_stream = stdout_stream.decode('utf-8')
if not isinstance(stderr_stream, str):
stderr_stream = stderr_stream.decode('utf-8')
stdout = stdout_stream.splitlines()
stderr = stderr_stream.splitlines()
if returncode != 0:
# set to true so that we can log the stderr/stdout that callers would
# do anyway as long as verbose_on_failure is set (defaults to True)
if verbose_on_failure:
terminal_verbose = True
# logfiles aren't disruptive visually, unlike the terminal, so this
# should always be on when there is a failure
logfile_verbose = True
# the following can get a messed up order in the log if the system call
# returns output with both stderr and stdout intermingled. This separates
# that.
for line in stdout:
log_output('stdout', line, terminal_verbose, logfile_verbose)
for line in stderr:
log_output('stderr', line, terminal_verbose, logfile_verbose)
return stdout, stderr, returncode
|
