Log service start timeout.
[oweals/dinit.git] / src / baseproc-service.cc
1 #include <cstring>
2 #include <cstdlib>
3
4 #include <sys/un.h>
5 #include <sys/socket.h>
6 #include <sys/types.h>
7 #include <sys/stat.h>
8 #include <unistd.h>
9
10 #include "dinit.h"
11 #include "dinit-log.h"
12 #include "dinit-socket.h"
13 #include "proc-service.h"
14
15 #include "baseproc-sys.h"
16
17 /*
18  * Base process implementation (base_process_service).
19  *
20  * See proc-service.h for interface documentation.
21  */
22
23 void base_process_service::do_smooth_recovery() noexcept
24 {
25     if (! restart_ps_process()) {
26         emergency_stop();
27         services->process_queues();
28     }
29 }
30
31 bool base_process_service::bring_up() noexcept
32 {
33     if (restarting) {
34         if (pid == -1) {
35             return restart_ps_process();
36         }
37         return true;
38     }
39     else {
40         if (! open_socket()) {
41             return false;
42         }
43
44         event_loop.get_time(restart_interval_time, clock_type::MONOTONIC);
45         restart_interval_count = 0;
46         if (start_ps_process(exec_arg_parts, onstart_flags.starts_on_console)) {
47             // Note: we don't set a start timeout for PROCESS services.
48             if (start_timeout != time_val(0,0) && get_type() != service_type_t::PROCESS) {
49                 restart_timer.arm_timer_rel(event_loop, start_timeout);
50                 stop_timer_armed = true;
51             }
52             else if (stop_timer_armed) {
53                 restart_timer.stop_timer(event_loop);
54                 stop_timer_armed = false;
55             }
56             return true;
57         }
58         return false;
59     }
60 }
61
62 bool base_process_service::start_ps_process(const std::vector<const char *> &cmd, bool on_console) noexcept
63 {
64     // In general, you can't tell whether fork/exec is successful. We use a pipe to communicate
65     // success/failure from the child to the parent. The pipe is set CLOEXEC so a successful
66     // exec closes the pipe, and the parent sees EOF. If the exec is unsuccessful, the errno
67     // is written to the pipe, and the parent can read it.
68
69     event_loop.get_time(last_start_time, clock_type::MONOTONIC);
70
71     int pipefd[2];
72     if (bp_sys::pipe2(pipefd, O_CLOEXEC)) {
73         log(loglevel_t::ERROR, get_name(), ": can't create status check pipe: ", strerror(errno));
74         return false;
75     }
76
77     const char * logfile = this->logfile.c_str();
78     if (*logfile == 0) {
79         logfile = "/dev/null";
80     }
81
82     bool child_status_registered = false;
83     control_conn_t *control_conn = nullptr;
84
85     int control_socket[2] = {-1, -1};
86     if (onstart_flags.pass_cs_fd) {
87         if (dinit_socketpair(AF_UNIX, SOCK_STREAM, /* protocol */ 0, control_socket, SOCK_NONBLOCK)) {
88             log(loglevel_t::ERROR, get_name(), ": can't create control socket: ", strerror(errno));
89             goto out_p;
90         }
91
92         // Make the server side socket close-on-exec:
93         int fdflags = bp_sys::fcntl(control_socket[0], F_GETFD);
94         bp_sys::fcntl(control_socket[0], F_SETFD, fdflags | FD_CLOEXEC);
95
96         try {
97             control_conn = new control_conn_t(event_loop, services, control_socket[0]);
98         }
99         catch (std::exception &exc) {
100             log(loglevel_t::ERROR, get_name(), ": can't launch process; out of memory");
101             goto out_cs;
102         }
103     }
104
105     // Set up complete, now fork and exec:
106
107     pid_t forkpid;
108
109     try {
110         child_status_listener.add_watch(event_loop, pipefd[0], dasynq::IN_EVENTS);
111         child_status_registered = true;
112
113         // We specify a high priority (i.e. low priority value) so that process termination is
114         // handled early. This means we have always recorded that the process is terminated by the
115         // time that we handle events that might otherwise cause us to signal the process, so we
116         // avoid sending a signal to an invalid (and possibly recycled) process ID.
117         forkpid = child_listener.fork(event_loop, reserved_child_watch, dasynq::DEFAULT_PRIORITY - 10);
118         reserved_child_watch = true;
119     }
120     catch (std::exception &e) {
121         log(loglevel_t::ERROR, get_name(), ": Could not fork: ", e.what());
122         goto out_cs_h;
123     }
124
125     if (forkpid == 0) {
126         const char * working_dir_c = nullptr;
127         if (! working_dir.empty()) working_dir_c = working_dir.c_str();
128         run_child_proc(cmd.data(), working_dir_c, logfile, on_console, pipefd[1], control_socket[1],
129                 socket_fd, run_as_uid, run_as_gid);
130     }
131     else {
132         // Parent process
133         bp_sys::close(pipefd[1]); // close the 'other end' fd
134         if (control_socket[1] != -1) {
135             bp_sys::close(control_socket[1]);
136         }
137         pid = forkpid;
138
139         waiting_for_execstat = true;
140         return true;
141     }
142
143     // Failure exit:
144
145     out_cs_h:
146     if (child_status_registered) {
147         child_status_listener.deregister(event_loop);
148     }
149
150     if (onstart_flags.pass_cs_fd) {
151         delete control_conn;
152
153         out_cs:
154         bp_sys::close(control_socket[0]);
155         bp_sys::close(control_socket[1]);
156     }
157
158     out_p:
159     bp_sys::close(pipefd[0]);
160     bp_sys::close(pipefd[1]);
161
162     return false;
163 }
164
165 base_process_service::base_process_service(service_set *sset, string name,
166         service_type_t service_type_p, string &&command,
167         std::list<std::pair<unsigned,unsigned>> &command_offsets,
168         const std::list<prelim_dep> &deplist_p)
169      : service_record(sset, name, service_type_p, deplist_p), child_listener(this),
170        child_status_listener(this), restart_timer(this)
171 {
172     program_name = std::move(command);
173     exec_arg_parts = separate_args(program_name, command_offsets);
174
175     restart_interval_count = 0;
176     restart_interval_time = {0, 0};
177     restart_timer.service = this;
178     restart_timer.add_timer(event_loop);
179
180     // By default, allow a maximum of 3 restarts within 10.0 seconds:
181     restart_interval.seconds() = 10;
182     restart_interval.nseconds() = 0;
183     max_restart_interval_count = 3;
184
185     waiting_restart_timer = false;
186     reserved_child_watch = false;
187     tracking_child = false;
188     stop_timer_armed = false;
189     start_is_interruptible = false;
190 }
191
192 void base_process_service::do_restart() noexcept
193 {
194     waiting_restart_timer = false;
195     restart_interval_count++;
196     auto service_state = get_state();
197
198     if (service_state == service_state_t::STARTING) {
199         // for a smooth recovery, we want to check dependencies are available before actually
200         // starting:
201         if (! check_deps_started()) {
202             waiting_for_deps = true;
203             return;
204         }
205     }
206
207     if (! start_ps_process(exec_arg_parts, have_console)) {
208         restarting = false;
209         if (service_state == service_state_t::STARTING) {
210             failed_to_start();
211         }
212         else {
213             // desired_state = service_state_t::STOPPED;
214             forced_stop();
215         }
216         services->process_queues();
217     }
218 }
219
220 bool base_process_service::restart_ps_process() noexcept
221 {
222     using time_val = dasynq::time_val;
223
224     time_val current_time;
225     event_loop.get_time(current_time, clock_type::MONOTONIC);
226
227     if (max_restart_interval_count != 0) {
228         // Check whether we're still in the most recent restart check interval:
229         time_val int_diff = current_time - restart_interval_time;
230         if (int_diff < restart_interval) {
231             if (restart_interval_count >= max_restart_interval_count) {
232                 log(loglevel_t::ERROR, "Service ", get_name(), " restarting too quickly; stopping.");
233                 return false;
234             }
235         }
236         else {
237             restart_interval_time = current_time;
238             restart_interval_count = 0;
239         }
240     }
241
242     // Check if enough time has lapsed since the previous restart. If not, start a timer:
243     time_val tdiff = current_time - last_start_time;
244     if (restart_delay <= tdiff) {
245         // > restart delay (normally 200ms)
246         do_restart();
247     }
248     else {
249         time_val timeout = restart_delay - tdiff;
250         restart_timer.arm_timer_rel(event_loop, timeout);
251         waiting_restart_timer = true;
252     }
253     return true;
254 }
255
256 bool base_process_service::interrupt_start() noexcept
257 {
258     if (waiting_restart_timer) {
259         restart_timer.stop_timer(event_loop);
260         waiting_restart_timer = false;
261         return service_record::interrupt_start();
262     }
263     else {
264         log(loglevel_t::WARN, "Interrupting start of service ", get_name(), " with pid ", pid, " (with SIGINT).");
265         kill_pg(SIGINT);
266         if (stop_timeout != time_val(0,0)) {
267             restart_timer.arm_timer_rel(event_loop, stop_timeout);
268             stop_timer_armed = true;
269         }
270         else if (stop_timer_armed) {
271             restart_timer.stop_timer(event_loop);
272             stop_timer_armed = false;
273         }
274         set_state(service_state_t::STOPPING);
275         notify_listeners(service_event_t::STARTCANCELLED);
276         return false;
277     }
278 }
279
280 void base_process_service::kill_with_fire() noexcept
281 {
282     if (pid != -1) {
283         log(loglevel_t::WARN, "Service ", get_name(), " with pid ", pid, " exceeded allowed stop time; killing.");
284         kill_pg(SIGKILL);
285     }
286 }
287
288 void base_process_service::kill_pg(int signo) noexcept
289 {
290     pid_t pgid = bp_sys::getpgid(pid);
291     if (pgid == -1) {
292         // only should happen if pid is invalid, which should never happen...
293         log(loglevel_t::ERROR, get_name(), ": can't signal process: ", strerror(errno));
294         return;
295     }
296     bp_sys::kill(-pgid, signo);
297 }
298
299 void base_process_service::timer_expired() noexcept
300 {
301     stop_timer_armed = false;
302
303     // Timer expires if:
304     // We are stopping, including after having startup cancelled (stop timeout, state is STOPPING); We are
305     // starting (start timeout, state is STARTING); We are waiting for restart timer before restarting,
306     // including smooth recovery (restart timeout, state is STARTING or STARTED).
307     if (get_state() == service_state_t::STOPPING) {
308         kill_with_fire();
309     }
310     else if (pid != -1) {
311         // Starting, start timed out.
312         log(loglevel_t::WARN, "Service ", get_name(), " with pid ", pid, " exceeded allowed start time.");
313         stop_dependents();
314         if (start_explicit) {
315             start_explicit = false;
316             release();
317         }
318         interrupt_start();
319     }
320     else {
321         // STARTING / STARTED, and we have a pid: must be restarting (smooth recovery if STARTED)
322         do_restart();
323     }
324 }
325
326 void base_process_service::emergency_stop() noexcept
327 {
328     if (! do_auto_restart() && start_explicit) {
329         start_explicit = false;
330         release(false);
331     }
332     forced_stop();
333     stop_dependents();
334 }
335
336 void base_process_service::becoming_inactive() noexcept
337 {
338     if (socket_fd != -1) {
339         close(socket_fd);
340         socket_fd = -1;
341     }
342 }
343
344 bool base_process_service::open_socket() noexcept
345 {
346     if (socket_path.empty() || socket_fd != -1) {
347         // No socket, or already open
348         return true;
349     }
350
351     const char * saddrname = socket_path.c_str();
352
353     // Check the specified socket path
354     struct stat stat_buf;
355     if (stat(saddrname, &stat_buf) == 0) {
356         if ((stat_buf.st_mode & S_IFSOCK) == 0) {
357             // Not a socket
358             log(loglevel_t::ERROR, get_name(), ": Activation socket file exists (and is not a socket)");
359             return false;
360         }
361     }
362     else if (errno != ENOENT) {
363         // Other error
364         log(loglevel_t::ERROR, get_name(), ": Error checking activation socket: ", strerror(errno));
365         return false;
366     }
367
368     // Remove stale socket file (if it exists).
369     // We won't test the return from unlink - if it fails other than due to ENOENT, we should get an
370     // error when we try to create the socket anyway.
371     unlink(saddrname);
372
373     uint sockaddr_size = offsetof(struct sockaddr_un, sun_path) + socket_path.length() + 1;
374     struct sockaddr_un * name = static_cast<sockaddr_un *>(malloc(sockaddr_size));
375     if (name == nullptr) {
376         log(loglevel_t::ERROR, get_name(), ": Opening activation socket: out of memory");
377         return false;
378     }
379
380     name->sun_family = AF_UNIX;
381     strcpy(name->sun_path, saddrname);
382
383     int sockfd = dinit_socket(AF_UNIX, SOCK_STREAM, 0, SOCK_NONBLOCK | SOCK_CLOEXEC);
384     if (sockfd == -1) {
385         log(loglevel_t::ERROR, get_name(), ": Error creating activation socket: ", strerror(errno));
386         free(name);
387         return false;
388     }
389
390     if (bind(sockfd, (struct sockaddr *) name, sockaddr_size) == -1) {
391         log(loglevel_t::ERROR, get_name(), ": Error binding activation socket: ", strerror(errno));
392         close(sockfd);
393         free(name);
394         return false;
395     }
396
397     free(name);
398
399     // POSIX (1003.1, 2013) says that fchown and fchmod don't necessarily work on sockets. We have to
400     // use chown and chmod instead.
401     if (chown(saddrname, socket_uid, socket_gid)) {
402         log(loglevel_t::ERROR, get_name(), ": Error setting activation socket owner/group: ", strerror(errno));
403         close(sockfd);
404         return false;
405     }
406
407     if (chmod(saddrname, socket_perms) == -1) {
408         log(loglevel_t::ERROR, get_name(), ": Error setting activation socket permissions: ", strerror(errno));
409         close(sockfd);
410         return false;
411     }
412
413     if (listen(sockfd, 128) == -1) { // 128 "seems reasonable".
414         log(loglevel_t::ERROR, ": Error listening on activation socket: ", strerror(errno));
415         close(sockfd);
416         return false;
417     }
418
419     socket_fd = sockfd;
420     return true;
421 }