xref: /openbmc/btbridge/btbridged.c (revision a28444b6)
1 /* Copyright 2015 IBM
2  *
3  * Licensed under the Apache License, Version 2.0 (the "License");
4  * you may not use this file except in compliance with the License.
5  * You may obtain a copy of the License at
6  *
7  *    http://www.apache.org/licenses/LICENSE-2.0
8  *
9  *	Unless required by applicable law or agreed to in writing, software
10  *	distributed under the License is distributed on an "AS IS" BASIS,
11  *	WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12  *	See the License for the specific language governing permissions and
13  *	limitations under the License.
14  */
15 
16 #include <assert.h>
17 #include <errno.h>
18 #include <fcntl.h>
19 #include <getopt.h>
20 #include <limits.h>
21 #include <poll.h>
22 #include <stdint.h>
23 #include <stdio.h>
24 #include <stdlib.h>
25 #include <string.h>
26 #include <syslog.h>
27 #include <sys/mman.h>
28 #include <sys/ioctl.h>
29 #include <sys/stat.h>
30 #include <sys/timerfd.h>
31 #include <time.h>
32 #include <unistd.h>
33 
34 #include <linux/bt-host.h>
35 
36 #include <systemd/sd-bus.h>
37 
38 #define PREFIX "BTBRIDGED"
39 
40 #define BT_HOST_PATH "/dev/bt-host"
41 #define BT_HOST_TIMEOUT_SEC 1
42 #define BT_MAX_MESSAGE 64
43 
44 #define DBUS_NAME "org.openbmc.HostIpmi"
45 #define OBJ_NAME "/org/openbmc/HostIpmi/1"
46 
47 #define SD_BUS_FD 0
48 #define BT_FD 1
49 #define TIMER_FD 2
50 #define TOTAL_FDS 3
51 
52 #define MSG_OUT(f_, ...) do { if (verbosity != BT_LOG_NONE) { bt_log(LOG_INFO, f_, ##__VA_ARGS__); } } while(0)
53 #define MSG_ERR(f_, ...) do { if (verbosity != BT_LOG_NONE) { bt_log(LOG_ERR, f_, ##__VA_ARGS__); } } while(0)
54 
55 struct ipmi_msg {
56 	uint8_t netfn;
57 	uint8_t lun;
58 	uint8_t seq;
59 	uint8_t cmd;
60 	uint8_t cc; /* Only used on responses */
61 	uint8_t *data;
62 	size_t data_len;
63 };
64 
65 struct bt_queue {
66 	struct ipmi_msg req;
67 	struct ipmi_msg rsp;
68 	struct timespec start;
69 	int expired;
70 	sd_bus_message *call;
71 	struct bt_queue *next;
72 };
73 
74 struct btbridged_context {
75 	struct pollfd fds[TOTAL_FDS];
76 	struct sd_bus *bus;
77 	struct bt_queue *bt_q;
78 };
79 
80 static void (*bt_vlog)(int p, const char *fmt, va_list args);
81 static int running = 1;
82 static enum {
83    BT_LOG_NONE = 0,
84    BT_LOG_VERBOSE,
85    BT_LOG_DEBUG
86 } verbosity;
87 
88 static void bt_log_console(int p, const char *fmt, va_list args)
89 {
90 	struct timespec time;
91 	FILE *s = (p < LOG_WARNING) ? stdout : stderr;
92 
93 	clock_gettime(CLOCK_REALTIME, &time);
94 
95 	fprintf(s, "[%s %ld.%.9ld] ", PREFIX, time.tv_sec, time.tv_nsec);
96 
97 	vfprintf(s, fmt, args);
98 }
99 
100 __attribute__((format(printf, 2, 3)))
101 static void bt_log(int p, const char *fmt, ...)
102 {
103 	va_list args;
104 
105 	va_start(args, fmt);
106 	bt_vlog(p, fmt, args);
107 	va_end(args);
108 }
109 
110 static struct bt_queue *bt_q_get_head(struct btbridged_context *context)
111 {
112 	return context ? context->bt_q : NULL;
113 }
114 
115 static struct bt_queue *bt_q_get_seq(struct btbridged_context *context, uint8_t seq)
116 {
117 	struct bt_queue *t;
118 
119 	assert(context);
120 
121 	t = context->bt_q;
122 
123 	while (t && t->req.seq != seq)
124 		t = t->next;
125 
126 	return t;
127 }
128 
129 static struct bt_queue *bt_q_get_msg(struct btbridged_context *context)
130 {
131 	struct bt_queue *t;
132 
133 	assert(context);
134 
135 	t = context->bt_q;
136 
137 	while (t && (!t->call && !t->expired))
138 		t = t->next;
139 
140 	return t;
141 }
142 
143 static struct bt_queue *bt_q_enqueue(struct btbridged_context *context, uint8_t *bt_data)
144 {
145 	struct bt_queue *n;
146 	struct bt_queue *bt_q;
147 	int len;
148 
149 	assert(context && bt_data);
150 
151 	/*
152 	 * len here is the length of the array.
153 	 * Helpfully BT doesn't count the length byte
154 	 */
155 	len = bt_data[0] + 1;
156 	if (len < 4) {
157 		MSG_ERR("Trying to queue a BT message with a short length (%d)\n", len);
158 		return NULL;
159 	}
160 
161 	bt_q = context->bt_q;
162 
163 	n = calloc(1, sizeof(struct bt_queue));
164 	if (!n)
165 		return NULL;
166 
167 	if (verbosity == BT_LOG_DEBUG) {
168 		n->req.data = malloc(len - 4);
169 		if (n->req.data)
170 			n->req.data = memcpy(n->req.data, bt_data + 4, len - 4);
171 	}
172 	n->req.data_len = len - 4;
173 	/* Don't count the lenfn/ln, seq and command */
174 	n->req.netfn = bt_data[1] >> 2;
175 	n->req.lun = bt_data[1] & 0x3;
176 	n->req.seq = bt_data[2];
177 	n->req.cmd = bt_data[3];
178 	if (clock_gettime(CLOCK_MONOTONIC, &n->start) == -1) {
179 		MSG_ERR("Couldn't clock_gettime(): %s\n", strerror(errno));
180 		free(n);
181 		return NULL;
182 	}
183 	if (!bt_q) {
184 		context->bt_q = n;
185 	} else {
186 		struct bt_queue *t = bt_q;
187 
188 		while (t->next)
189 			t = t->next;
190 
191 		t->next = n;
192 	}
193 
194 	return n;
195 }
196 
197 static void bt_q_free(struct bt_queue *bt_q)
198 {
199 	if (!bt_q)
200 		return;
201 
202 	/* Unrefing sd_bus_message should free(rsp.data) */
203 	if (bt_q->call)
204 		sd_bus_message_unref(bt_q->call);
205 
206 	free(bt_q->req.data);
207 	free(bt_q);
208 }
209 
210 static struct bt_queue *bt_q_drop(struct btbridged_context *context, struct bt_queue *element)
211 {
212 	struct bt_queue *r;
213 	struct bt_queue *bt_q;
214 
215 	assert(context);
216 
217 	bt_q = context->bt_q;
218 	if (!element || !bt_q)
219 		return NULL;
220 
221 
222 	r = bt_q;
223 	if (r == bt_q) {
224 		context->bt_q = bt_q->next;
225 	} else {
226 		while (r && r->next != element)
227 			r = r->next;
228 
229 		if (!r) {
230 			MSG_ERR("Didn't find element %p in queue\n", element);
231 			bt_q_free(element);
232 			return NULL;
233 		}
234 		r->next = r->next->next;
235 	}
236 	bt_q_free(element);
237 
238 	return context->bt_q;
239 }
240 
241 static struct bt_queue *bt_q_dequeue(struct btbridged_context *context)
242 {
243 	struct bt_queue *r;
244 	struct bt_queue *bt_q;
245 
246 	assert(context);
247 
248 	bt_q = context->bt_q;
249 	if (!bt_q) {
250 		MSG_ERR("Dequeuing empty queue!\n");
251 		return NULL;
252 	}
253 
254 	r = bt_q->next;
255 	bt_q_free(bt_q);
256 	context->bt_q = r;
257 
258 	return r;
259 }
260 
261 static int method_send_sms_atn(sd_bus_message *msg, void *userdata,
262 			       sd_bus_error *ret_error)
263 {
264 	int r;
265 	struct btbridged_context *bt_fd = userdata;
266 
267 	MSG_OUT("Sending SMS_ATN ioctl (%d) to %s\n",
268 			BT_HOST_IOCTL_SMS_ATN, BT_HOST_PATH);
269 
270 	r = ioctl(bt_fd->fds[BT_FD].fd, BT_HOST_IOCTL_SMS_ATN);
271 	if (r == -1) {
272 		r = errno;
273 		MSG_ERR("Couldn't ioctl() to 0x%x, %s: %s\n", bt_fd->fds[BT_FD].fd, BT_HOST_PATH, strerror(r));
274 		return sd_bus_reply_method_errno(msg, errno, ret_error);
275 	}
276 
277 	r = 0;
278 	return sd_bus_reply_method_return(msg, "x", r);
279 }
280 
281 static int method_send_message(sd_bus_message *msg, void *userdata, sd_bus_error *ret_error)
282 {
283 	struct btbridged_context *context;
284 	struct bt_queue *bt_msg;
285 	uint8_t *data;
286 	size_t data_sz;
287 	uint8_t netfn, lun, seq, cmd, cc;
288 	/*
289 	 * Doesn't say it anywhere explicitly but it looks like returning 0 or
290 	 * negative is BAD...
291 	 */
292 	int r = 1;
293 
294 	context = (struct btbridged_context *)userdata;
295 	if (!context) {
296 		sd_bus_error_set_const(ret_error, "org.openbmc.error", "Internal error");
297 		r = 0;
298 		goto out;
299 	}
300 	r = sd_bus_message_read(msg, "yyyyy", &seq, &netfn, &lun, &cmd, &cc);
301 	if (r < 0) {
302 		MSG_ERR("Couldn't parse leading bytes of message: %s\n", strerror(-r));
303 		sd_bus_error_set_const(ret_error, "org.openbmc.error", "Bad message");
304 		r = -EINVAL;
305 		goto out;
306 	}
307 	r = sd_bus_message_read_array(msg, 'y', (const void **)&data, &data_sz);
308 	if (r < 0) {
309 		MSG_ERR("Couldn't parse data bytes of message: %s\n", strerror(-r));
310 		sd_bus_error_set_const(ret_error, "org.openbmc.error", "Bad message data");
311 		r = -EINVAL;
312 		goto out;
313 	}
314 
315 	bt_msg = bt_q_get_seq(context, seq);
316 	if (!bt_msg) {
317 		sd_bus_error_set_const(ret_error, "org.openbmc.error", "No matching request");
318 		MSG_ERR("Failed to find matching request for dbus method with seq: 0x%02x\n", seq);
319 		r = -EINVAL;
320 		goto out;
321 	}
322 	MSG_OUT("Received a dbus response for msg with seq 0x%02x\n", seq);
323 	bt_msg->call = sd_bus_message_ref(msg);
324 	bt_msg->rsp.netfn = netfn;
325 	bt_msg->rsp.lun = lun;
326 	bt_msg->rsp.seq = seq;
327 	bt_msg->rsp.cmd = cmd;
328 	bt_msg->rsp.cc = cc;
329 	bt_msg->rsp.data_len = data_sz;
330 	/* Because we've ref'ed the msg, I hope we don't need to memcpy data */
331 	bt_msg->rsp.data = data;
332 
333 	/* Now that we have a response */
334 	context->fds[BT_FD].events |= POLLOUT;
335 
336 out:
337 	return r;
338 }
339 
340 static int bt_host_write(struct btbridged_context *context, struct bt_queue *bt_msg)
341 {
342 	struct bt_queue *head;
343 	uint8_t data[BT_MAX_MESSAGE] = { 0 };
344 	sd_bus_message *msg = NULL;
345 	int r, len;
346 
347 	assert(context);
348 
349 	if (!bt_msg)
350 		return -EINVAL;
351 
352 	head = bt_q_get_head(context);
353 	if (bt_msg == head) {
354 		struct itimerspec ts;
355 		/* Need to adjust the timer */
356 		ts.it_interval.tv_sec = 0;
357 		ts.it_interval.tv_nsec = 0;
358 		if (head->next) {
359 			ts.it_value = head->next->start;
360 			ts.it_value.tv_sec += BT_HOST_TIMEOUT_SEC;
361 			MSG_OUT("Adjusting timer for next element\n");
362 		} else {
363 			ts.it_value.tv_nsec = 0;
364 			ts.it_value.tv_sec = 0;
365 			MSG_OUT("Disabling timer, no elements remain in queue\n");
366 		}
367 		r = timerfd_settime(context->fds[TIMER_FD].fd, TFD_TIMER_ABSTIME, &ts, NULL);
368 		if (r == -1)
369 			MSG_ERR("Couldn't set timerfd\n");
370 	}
371 	data[1] = (bt_msg->rsp.netfn << 2) | (bt_msg->rsp.lun & 0x3);
372 	data[2] = bt_msg->rsp.seq;
373 	data[3] = bt_msg->rsp.cmd;
374 	data[4] = bt_msg->rsp.cc;
375 	if (bt_msg->rsp.data_len > sizeof(data) - 5) {
376 		MSG_ERR("Response message size (%zu) too big, truncating\n", bt_msg->rsp.data_len);
377 		bt_msg->rsp.data_len = sizeof(data) - 5;
378 	}
379 	/* netfn/len + seq + cmd + cc = 4 */
380 	data[0] = bt_msg->rsp.data_len + 4;
381 	if (bt_msg->rsp.data_len)
382 		memcpy(data + 5, bt_msg->rsp.data, bt_msg->rsp.data_len);
383 	/* Count the data[0] byte */
384 	len = write(context->fds[BT_FD].fd, data, data[0] + 1);
385 	if (len == -1) {
386 		r = errno;
387 		MSG_ERR("Error writing to %s: %s\n", BT_HOST_PATH, strerror(errno));
388 		if (bt_msg->call) {
389 			r = sd_bus_message_new_method_errno(bt_msg->call, &msg, r, NULL);
390 			if (r < 0)
391 				MSG_ERR("Couldn't create response error\n");
392 		}
393 		goto out;
394 	} else {
395 		if (len != data[0] + 1)
396 			MSG_ERR("Possible short write to %s, desired len: %d, written len: %d\n", BT_HOST_PATH, data[0] + 1, len);
397 		else
398 			MSG_OUT("Successfully wrote %d of %d bytes to %s\n", len, data[0] + 1, BT_HOST_PATH);
399 
400 		if (bt_msg->call) {
401 			r = sd_bus_message_new_method_return(bt_msg->call, &msg);
402 			if (r < 0) {
403 				MSG_ERR("Couldn't create response message\n");
404 				goto out;
405 			}
406 			r = 0; /* Just to be explicit about what we're sending back */
407 			r = sd_bus_message_append(msg, "x", r);
408 			if (r < 0) {
409 				MSG_ERR("Couldn't append result to response\n");
410 				goto out;
411 			}
412 
413 		}
414 	}
415 
416 out:
417 	if (bt_msg->call) {
418 		if (sd_bus_send(context->bus, msg, NULL) < 0)
419 			MSG_ERR("Couldn't send response message\n");
420 		sd_bus_message_unref(msg);
421 	}
422 	bt_q_drop(context, bt_msg);
423 
424 	/*
425 	 * There isn't another message ready to be sent so turn off POLLOUT
426 	 */
427 	if (!bt_q_get_msg(context)) {
428 		MSG_OUT("Turning off POLLOUT for the BT in poll()\n");
429 		context->fds[BT_FD].events = POLLIN;
430 	}
431 
432 	return r;
433 }
434 
435 static int dispatch_timer(struct btbridged_context *context)
436 {
437 	int r = 0;
438 	if (context->fds[TIMER_FD].revents & POLLIN) {
439 		sd_bus_message *msg;
440 		struct bt_queue *head;
441 
442 		head = bt_q_get_head(context);
443 		if (!head) {
444 			/* Odd, timer expired but we didn't have a message to timeout */
445 			MSG_ERR("No message found to send timeout\n");
446 			return 0;
447 		}
448 		if (head->call) {
449 			r = sd_bus_message_new_method_errno(head->call, &msg, ETIMEDOUT, NULL);
450 			if (r < 0) {
451 				MSG_ERR("Couldn't create response error\n");
452 			} else {
453 				if (sd_bus_send(context->bus, msg, NULL) < 0)
454 					MSG_ERR("Couldn't send response message\n");
455 				sd_bus_message_unref(msg);
456 			}
457 			MSG_ERR("Message with seq 0x%02x is being timed out despite "
458 					"appearing to have been responded to. Slow BT?\n", head->rsp.seq);
459 		}
460 
461 		/* Set expiry */
462 		head->expired = 1;
463 		head->rsp.seq = head->req.seq;
464 		head->rsp.netfn = head->req.netfn + 1;
465 		head->rsp.lun = head->req.lun;
466 		head->rsp.cc = 0xce; /* Command response could not be provided */
467 		head->rsp.cmd = head->req.cmd;
468 		/* These should already be zeroed but best to be sure */
469 		head->rsp.data_len = 0;
470 		head->rsp.data = NULL;
471 		head->call = NULL;
472 		MSG_OUT("Timeout on msg with seq: 0x%02x\n", head->rsp.seq);
473 		/* Turn on POLLOUT so we'll write this one next */
474 		context->fds[BT_FD].events |= POLLOUT;
475 	}
476 
477 	return 0;
478 }
479 
480 static int dispatch_sd_bus(struct btbridged_context *context)
481 {
482 	int r = 0;
483 	if (context->fds[SD_BUS_FD].revents) {
484 		r = sd_bus_process(context->bus, NULL);
485 		if (r > 0)
486 			MSG_OUT("Processed %d dbus events\n", r);
487 	}
488 
489 	return r;
490 }
491 
492 static int dispatch_bt(struct btbridged_context *context)
493 {
494 	int err = 0;
495 	int r;
496 
497 	assert(context);
498 
499 	if (context->fds[BT_FD].revents & POLLIN) {
500 		sd_bus_message *msg;
501 		struct bt_queue *new;
502 		uint8_t data[BT_MAX_MESSAGE] = { 0 };
503 
504 		r = read(context->fds[BT_FD].fd, data, sizeof(data));
505 		if (r < 0) {
506 			MSG_ERR("Couldn't read from bt: %s\n", strerror(-r));
507 			goto out1;
508 		}
509 		if (r < data[0] + 1) {
510 			MSG_ERR("Short read from bt (%d vs %d)\n", r, data[0] + 1);
511 			r = 0;
512 			goto out1;
513 		}
514 
515 		new = bt_q_enqueue(context, data);
516 		if (!new) {
517 			r = -ENOMEM;
518 			goto out1;
519 		}
520 		if (new == bt_q_get_head(context)) {
521 			struct itimerspec ts;
522 			/*
523 			 * Enqueued onto an empty list, setup a timer for sending a
524 			 * timeout
525 			 */
526 			ts.it_interval.tv_sec = 0;
527 			ts.it_interval.tv_nsec = 0;
528 			ts.it_value.tv_nsec = 0;
529 			ts.it_value.tv_sec = BT_HOST_TIMEOUT_SEC;
530 			r = timerfd_settime(context->fds[TIMER_FD].fd, 0, &ts, NULL);
531 			if (r == -1)
532 				MSG_ERR("Couldn't set timerfd\n");
533 		}
534 
535 		r = sd_bus_message_new_signal(context->bus, &msg, OBJ_NAME, DBUS_NAME, "ReceivedMessage");
536 		if (r < 0) {
537 			MSG_ERR("Failed to create signal: %s\n", strerror(-r));
538 			goto out1;
539 		}
540 
541 		r = sd_bus_message_append(msg, "yyyy", new->req.seq, new->req.netfn, new->req.lun, new->req.cmd);
542 		if (r < 0) {
543 			MSG_ERR("Couldn't append to signal: %s\n", strerror(-r));
544 			goto out1_free;
545 		}
546 
547 		r = sd_bus_message_append_array(msg, 'y', data + 4, new->req.data_len);
548 		if (r < 0) {
549 			MSG_ERR("Couldn't append array to signal: %s\n", strerror(-r));
550 			goto out1_free;
551 		}
552 
553 		MSG_OUT("Sending dbus signal with seq 0x%02x, netfn 0x%02x, lun 0x%02x, cmd 0x%02x\n",
554 				new->req.seq, new->req.netfn, new->req.lun, new->req.cmd);
555 
556 		if (verbosity == BT_LOG_DEBUG) {
557 			int i;
558 			for (i = 0; i < new->req.data_len; i++) {
559 				if (i % 8 == 0) {
560 					if (i)
561 						printf("\n");
562 					MSG_OUT("\t");
563 				}
564 				printf("0x%02x ", data[i + 4]);
565 			}
566 			if (new->req.data_len)
567 				printf("\n");
568 		}
569 
570 		/* Note we only actually keep the request data in the queue when debugging */
571 		r = sd_bus_send(context->bus, msg, NULL);
572 		if (r < 0) {
573 			MSG_ERR("Couldn't emit dbus signal: %s\n", strerror(-r));
574 			goto out1_free;
575 		}
576 		r = 0;
577 out1_free:
578 		sd_bus_message_unref(msg);
579 out1:
580 		err = r;
581 	}
582 
583 	if (context->fds[BT_FD].revents & POLLOUT) {
584 		struct bt_queue *bt_msg;
585 		bt_msg = bt_q_get_msg(context);
586 		if (!bt_msg) {
587 			/* Odd, this shouldn't really happen */
588 			MSG_ERR("Got a POLLOUT but no message is ready to be written\n");
589 			r = 0;
590 			goto out;
591 		}
592 		r = bt_host_write(context, bt_msg);
593 		if (r < 0)
594 			MSG_ERR("Problem putting request with seq 0x%02x, netfn 0x%02x, lun 0x%02x, cmd 0x%02x, cc 0x%02x\n"
595 					"out to %s", bt_msg->rsp.seq, bt_msg->rsp.netfn, bt_msg->rsp.lun,
596 					bt_msg->rsp.cmd, bt_msg->rsp.cc, BT_HOST_PATH);
597 		else
598 			MSG_OUT("Completed request with seq 0x%02x, netfn 0x%02x, lun 0x%02x, cmd 0x%02x, cc 0x%02x\n",
599 					bt_msg->rsp.seq, bt_msg->rsp.netfn, bt_msg->rsp.lun, bt_msg->rsp.cmd, bt_msg->rsp.cc);
600 	}
601 out:
602 	return err ? err : r;
603 }
604 
605 static void usage(const char *name)
606 {
607 	fprintf(stderr, "Usage %s [ --v[v] | --syslog ]\n", name);
608 	fprintf(stderr, "\t--v\t Be verbose\n");
609 	fprintf(stderr, "\t--vv\t Be verbose and dump entire messages\n");
610 	fprintf(stderr, "\t--syslog\t Log output to syslog (pointless without --verbose)\n\n");
611 }
612 
613 static const sd_bus_vtable ipmid_vtable[] = {
614 	SD_BUS_VTABLE_START(0),
615 	SD_BUS_METHOD("sendMessage", "yyyyyay", "x", &method_send_message, SD_BUS_VTABLE_UNPRIVILEGED),
616 	SD_BUS_METHOD("setAttention", "", "x", &method_send_sms_atn, SD_BUS_VTABLE_UNPRIVILEGED),
617 	SD_BUS_SIGNAL("ReceivedMessage", "yyyyay", 0),
618 	SD_BUS_VTABLE_END
619 };
620 
621 int main(int argc, char *argv[]) {
622 	struct btbridged_context *context;
623 	const char *name = argv[0];
624 	int opt, polled, r;
625 
626 	static const struct option long_options[] = {
627 		{ "v",       no_argument, (int *)&verbosity, BT_LOG_VERBOSE },
628 		{ "vv",      no_argument, (int *)&verbosity, BT_LOG_DEBUG   },
629 		{ "syslog",  no_argument, 0,          's'         },
630 		{ 0,         0,           0,          0           }
631 	};
632 
633 	context = calloc(1, sizeof(*context));
634 
635 	bt_vlog = &bt_log_console;
636 	while ((opt = getopt_long(argc, argv, "", long_options, NULL)) != -1) {
637 		switch (opt) {
638 			case 0:
639 				break;
640 			case 's':
641 				/* Avoid a double openlog() */
642 				if (bt_vlog != &vsyslog) {
643 					openlog(PREFIX, LOG_ODELAY, LOG_DAEMON);
644 					bt_vlog = &vsyslog;
645 				}
646 				break;
647 			default:
648 				usage(name);
649 				exit(EXIT_FAILURE);
650 		}
651 	}
652 
653 	if (verbosity == BT_LOG_VERBOSE)
654 		MSG_OUT("Verbose logging\n");
655 
656 	if (verbosity == BT_LOG_DEBUG)
657 		MSG_OUT("Debug logging\n");
658 
659 	MSG_OUT("Starting\n");
660 	r = sd_bus_default_system(&context->bus);
661 	if (r < 0) {
662 		MSG_ERR("Failed to connect to system bus: %s\n", strerror(-r));
663 		goto finish;
664 	}
665 
666 	MSG_OUT("Registering dbus methods/signals\n");
667 	r = sd_bus_add_object_vtable(context->bus,
668 	                             NULL,
669 	                             OBJ_NAME,
670 	                             DBUS_NAME,
671 	                             ipmid_vtable,
672 	                             context);
673 	if (r < 0) {
674 		MSG_ERR("Failed to issue method call: %s\n", strerror(-r));
675 		goto finish;
676 	}
677 
678 	MSG_OUT("Requesting dbus name: %s\n", DBUS_NAME);
679 	r = sd_bus_request_name(context->bus, DBUS_NAME, SD_BUS_NAME_ALLOW_REPLACEMENT|SD_BUS_NAME_REPLACE_EXISTING);
680 	if (r < 0) {
681 		MSG_ERR("Failed to acquire service name: %s\n", strerror(-r));
682 		goto finish;
683 	}
684 
685 	MSG_OUT("Getting dbus file descriptors\n");
686 	context->fds[SD_BUS_FD].fd = sd_bus_get_fd(context->bus);
687 	if (context->fds[SD_BUS_FD].fd < 0) {
688 		r = -errno;
689 		MSG_OUT("Couldn't get the bus file descriptor: %s\n", strerror(errno));
690 		goto finish;
691 	}
692 
693 	MSG_OUT("Opening %s\n", BT_HOST_PATH);
694 	context->fds[BT_FD].fd = open(BT_HOST_PATH, O_RDWR | O_NONBLOCK);
695 	if (context->fds[BT_FD].fd < 0) {
696 		r = -errno;
697 		MSG_ERR("Couldn't open %s with flags O_RDWR: %s\n", BT_HOST_PATH, strerror(errno));
698 		goto finish;
699 	}
700 
701 	MSG_OUT("Creating timer fd\n");
702 	context->fds[TIMER_FD].fd = timerfd_create(CLOCK_MONOTONIC, 0);
703 	if (context->fds[TIMER_FD].fd < 0) {
704 		r = -errno;
705 		MSG_ERR("Couldn't create timer fd: %s\n", strerror(errno));
706 		goto finish;
707 	}
708 	context->fds[SD_BUS_FD].events = POLLIN;
709 	context->fds[BT_FD].events = POLLIN;
710 	context->fds[TIMER_FD].events = POLLIN;
711 
712 	MSG_OUT("Entering polling loop\n");
713 
714 	while (running) {
715 		polled = poll(context->fds, TOTAL_FDS, 1000);
716 		if (polled == 0)
717 			continue;
718 		if (polled < 0) {
719 			r = -errno;
720 			MSG_ERR("Error from poll(): %s\n", strerror(errno));
721 			goto finish;
722 		}
723 		r = dispatch_sd_bus(context);
724 		if (r < 0) {
725 			MSG_ERR("Error handling dbus event: %s\n", strerror(-r));
726 			goto finish;
727 		}
728 		r = dispatch_bt(context);
729 		if (r < 0) {
730 			MSG_ERR("Error handling BT event: %s\n", strerror(-r));
731 			goto finish;
732 		}
733 		r = dispatch_timer(context);
734 		if (r < 0) {
735 			MSG_ERR("Error handling timer event: %s\n", strerror(-r));
736 			goto finish;
737 		}
738 	}
739 
740 finish:
741 	if (bt_q_get_head(context)) {
742 		MSG_ERR("Unresponded BT Message!\n");
743 		while (bt_q_dequeue(context));
744 	}
745 	close(context->fds[BT_FD].fd);
746 	close(context->fds[TIMER_FD].fd);
747 	sd_bus_unref(context->bus);
748 	free(context);
749 
750 	return r;
751 }
752 
753