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