From ee54e01a696c9a59892c98cc740ada7bad52899d Mon Sep 17 00:00:00 2001 From: Ismo Puustinen Date: Wed, 12 Dec 2012 10:12:55 +0200 Subject: [PATCH] resource-asm: fix a bug in callback handling, add logging. --- src/plugins/plugin-resource-asm.c | 31 +++++++-- src/plugins/resource-asm/asm-bridge.c | 124 +++++++++++++++++++++++++--------- 2 files changed, 117 insertions(+), 38 deletions(-) diff --git a/src/plugins/plugin-resource-asm.c b/src/plugins/plugin-resource-asm.c index 2ee7935..dfaed46 100644 --- a/src/plugins/plugin-resource-asm.c +++ b/src/plugins/plugin-resource-asm.c @@ -104,6 +104,8 @@ typedef struct { uint32_t request_id; asm_data_t *ctx; + ASM_sound_states_t requested_state; + /* mutable */ request_type_t rtype; @@ -205,6 +207,19 @@ static void dump_outgoing_msg(asm_to_lib_t *msg, asm_data_t *ctx) msg->check_privilege ? "TRUE" : "FALSE"); } + +static void dump_outgoing_cb_msg(asm_to_lib_cb_t *msg, asm_data_t *ctx) +{ + MRP_UNUSED(ctx); + + mrp_log_info(" <-- client id: %u", msg->instance_id); + mrp_log_info(" <-- handle: %d", msg->handle); + mrp_log_info(" <-- expect callback: %d", msg->callback_expected); + mrp_log_info(" <-- sound command: 0x%04x", msg->sound_command); + mrp_log_info(" <-- event source: 0x%04x", msg->event_source); +} + + #if 0 static uint32_t encode_pid_handle(uint32_t pid, uint32_t handle) { @@ -298,16 +313,17 @@ static void event_cb(uint32_t request_id, mrp_resource_set_t *set, void *data) reply.alloc_handle = d->handle; reply.cmd_handle = d->handle; - reply.result_sound_command = ASM_COMMAND_NONE; + reply.result_sound_state = ASM_STATE_IGNORE; /* TODO: check the mask properly */ if (mrp_get_resource_set_grant(d->rset)) - reply.result_sound_state = ASM_STATE_PLAYING; + reply.result_sound_command = ASM_COMMAND_PLAY; else - reply.result_sound_state = ASM_STATE_STOP; + reply.result_sound_command = ASM_COMMAND_STOP; d->rtype = request_type_server_event; + /* FIXME: only send reply when "PLAYING" state was requested? */ dump_outgoing_msg(&reply, ctx); mrp_transport_senddata(ctx->t, &reply, TAG_ASM_TO_LIB); break; @@ -333,8 +349,11 @@ static void event_cb(uint32_t request_id, mrp_resource_set_t *set, void *data) /* stop processing server_events */ d->request_id = 0; +#if 0 + /* no response needed for moving to state other than PLAYING */ dump_outgoing_msg(&reply, ctx); mrp_transport_senddata(ctx->t, &reply, TAG_ASM_TO_LIB); +#endif break; } case request_type_server_event: @@ -361,7 +380,7 @@ static void event_cb(uint32_t request_id, mrp_resource_set_t *set, void *data) if (mrp_get_resource_set_grant(d->rset)) { reply.sound_command = ASM_COMMAND_RESUME; /* ASM doesn't send callback to RESUME commands */ - reply.callback_expected = FALSE; + reply.callback_expected = TRUE; } else { reply.sound_command = ASM_COMMAND_PAUSE; @@ -371,7 +390,7 @@ static void event_cb(uint32_t request_id, mrp_resource_set_t *set, void *data) /* FIXME: the player-player case needs to be solved here? */ reply.event_source = ASM_EVENT_SOURCE_OTHER_PLAYER_APP; - dump_outgoing_msg(reply, ctx); + dump_outgoing_cb_msg(&reply, ctx); mrp_transport_senddata(ctx->t, &reply, TAG_ASM_TO_LIB_CB); break; @@ -649,10 +668,12 @@ static asm_to_lib_t *process_msg(lib_to_asm_t *msg, asm_data_t *ctx) } d->request_id = ++ctx->current_request; + d->requested_state = msg->sound_state; switch(msg->sound_state) { case ASM_STATE_PLAYING: { + /* requests done for "PLAYING" state need a reply, others don't */ d->rtype = request_type_acquire; mrp_log_info("requesting acquisition of playback rights" diff --git a/src/plugins/resource-asm/asm-bridge.c b/src/plugins/resource-asm/asm-bridge.c index 900630a..76fffc6 100644 --- a/src/plugins/resource-asm/asm-bridge.c +++ b/src/plugins/resource-asm/asm-bridge.c @@ -49,6 +49,7 @@ #include "asm-bridge.h" +FILE *logfile; typedef struct ctx_s { mrp_mainloop_t *ml; @@ -66,6 +67,44 @@ struct watched_file { }; +static int log_init(const char *filename) +{ + logfile = fopen(filename, "w"); + + if (!logfile) + return -1; + + return 0; +} + +static void log_write(char *format, ...) +{ + va_list ap; + + if (!logfile) + return; + + va_start(ap, format); + vfprintf(logfile, format, ap); + va_end(ap); + + fflush(logfile); + fdatasync(fileno(logfile)); +} + +static int log_close() +{ + if (!logfile) + return -1; + + fclose(logfile); + + logfile = NULL; + + return 0; +} + + static void *wait_queue (void *arg) { ASM_msg_lib_to_asm_t msg; @@ -75,7 +114,7 @@ static void *wait_queue (void *arg) { int fd = arg_thread[1]; if (asm_rcv_msgid == -1) { - mrp_log_error("failed to create the receive message queue\n"); + log_write("failed to create the receive message queue\n"); exit(1); } @@ -84,7 +123,7 @@ static void *wait_queue (void *arg) { if (ret < 0) { /* FIXME: proper error handling */ - mrp_log_error("error receiving a message: '%s'!", strerror(errno)); + log_write("error receiving a message: '%s'!\n", strerror(errno)); /* remove message from queue */ msgrcv(asm_rcv_msgid, &msg, sizeof(msg.data), 0, MSG_NOERROR); continue; @@ -102,22 +141,22 @@ static void dump_msg(ASM_msg_lib_to_asm_t *msg, ctx_t *ctx) { MRP_UNUSED(ctx); - mrp_log_info("Message id %ld:", msg->instance_id); + log_write("Message id %ld:\n", msg->instance_id); - mrp_log_info("Data handle: %d", msg->data.handle); - mrp_log_info(" request id: 0x%04x", msg->data.request_id); - mrp_log_info(" sound event: 0x%04x", msg->data.sound_event); - mrp_log_info(" sound state: 0x%04x", msg->data.sound_state); - mrp_log_info(" system resource: 0x%04x", msg->data.system_resource); + log_write("Data handle: %d\n", msg->data.handle); + log_write(" request id: 0x%04x\n", msg->data.request_id); + log_write(" sound event: 0x%04x\n", msg->data.sound_event); + log_write(" sound state: 0x%04x\n", msg->data.sound_state); + log_write(" system resource: 0x%04x\n", msg->data.system_resource); #ifdef USE_SECURITY { int i; - mrp_log_info(" cookie: "); + log_write(" cookie: "); for (i = 0; i < COOKIE_SIZE; i++) { - mrp_log_info("0x%02x ", msg->data.cookie[i]); + log_write("0x%02x ", msg->data.cookie[i]); } - mrp_log_info("\n"); + log_write("\n"); } #endif } @@ -148,7 +187,7 @@ static int process_msg(ASM_msg_lib_to_asm_t *msg, ctx_t *ctx) res.cookie = cookie; if (!mrp_transport_senddata(ctx->mt, &res, lib_to_asm_descr.tag)) { - mrp_log_error("Failed to send message to murphy"); + log_write("Failed to send message to murphy\n"); return -1; } @@ -171,14 +210,14 @@ static void pipe_cb(mrp_mainloop_t *ml, mrp_io_watch_t *w, int fd, bytes = read(fd, &msg, sizeof(ASM_msg_lib_to_asm_t)); if (bytes != sizeof(ASM_msg_lib_to_asm_t)) { - mrp_log_error("failed to read from the pipe"); + log_write("failed to read from the pipe\n"); return; } ret = process_msg(&msg, ctx); if (ret < 0) { - mrp_log_error("error parsing or proxying message"); + log_write("error parsing or proxying message\n"); } } @@ -205,14 +244,17 @@ static void read_watch_cb(mrp_mainloop_t *ml, mrp_io_watch_t *w, int fd, msg.handle = wf->handle; msg.cb_result = buf; + log_write("read 0x%08x from client %u.%d\n", + msg.cb_result, msg.instance_id, msg.handle); + if (!mrp_transport_senddata(ctx->mt, &msg, lib_to_asm_cb_descr.tag)) { - mrp_log_error("Failed to send message to murphy"); + log_write("Failed to send message to murphy\n"); } } } if (events & MRP_IO_EVENT_HUP) { /* can we assume that the client went away? */ - mrp_log_error("HUP event from client"); + log_write("HUP event from client\n"); } mrp_htbl_remove(ctx->watched_files, wf->watched_file, TRUE); @@ -239,11 +281,11 @@ static int send_callback_to_client(asm_to_lib_cb_t *msg, ctx_t *ctx) if (ret <= 0 || ret == ASM_FILENAME_SIZE) goto error; - mrp_log_info("writing client preemption to file %s", wr_filename); + log_write("writing client preemption to file %s\n", wr_filename); wr_fd = open(wr_filename, O_NONBLOCK | O_WRONLY); if (wr_fd < 0) { - mrp_log_error("failed to open file '%s' for writing: '%s'", wr_filename, + log_write("failed to open file '%s' for writing: '%s'", wr_filename, strerror(errno)); goto error; } @@ -256,9 +298,9 @@ static int send_callback_to_client(asm_to_lib_cb_t *msg, ctx_t *ctx) if (ret <= 0 || ret == ASM_FILENAME_SIZE) goto error; - rd_fd = open(wr_filename, O_NONBLOCK | O_RDONLY); + rd_fd = open(rd_filename, O_NONBLOCK | O_RDONLY); if (rd_fd < 0) { - mrp_log_error("failed to open file '%s' for reading: '%s'", + log_write("failed to open file '%s' for reading: '%s'\n", rd_filename, strerror(errno)); goto error; } @@ -268,10 +310,13 @@ static int send_callback_to_client(asm_to_lib_cb_t *msg, ctx_t *ctx) if (wf) { /* already watched, this is a bad thing */ - mrp_log_error("client %d.%u missed a callback notification", + log_write("client %d.%u missed a callback notification\n", msg->instance_id, msg->handle); } else { + log_write("starting to listen file '%s' for callback answers\n", + rd_filename); + wf = mrp_allocz(sizeof(struct watched_file)); if (!wf) @@ -297,11 +342,13 @@ static int send_callback_to_client(asm_to_lib_cb_t *msg, ctx_t *ctx) ret = write(wr_fd, &data, sizeof(uint32_t)); if (ret < (int) sizeof(uint32_t)) { - mrp_log_error("failed to write callback data to %d.%u", + log_write("failed to write callback data to %d.%u\n", msg->instance_id, msg->handle); goto error; } + log_write("wrote 0x%08x to %s\n", data, wr_filename); + close(wr_fd); return 0; @@ -350,7 +397,7 @@ static void recvfrom_murphy(mrp_transport_t *t, void *data, uint16_t tag, if (msgsnd(ctx->snd_msgq, (void *) &msg, sizeof(msg.data), 0) < 0) { - mrp_log_error("failed to send message to client"); + log_write("failed to send message to client\n"); } break; } @@ -358,13 +405,13 @@ static void recvfrom_murphy(mrp_transport_t *t, void *data, uint16_t tag, case TAG_ASM_TO_LIB_CB: { if (send_callback_to_client(data, ctx) < 0) { - mrp_log_error("failed to send callback message to client"); + log_write("failed to send callback message to client\n"); } break; } default: - mrp_log_error("Unknown message received!"); + log_write("Unknown message received!\n"); break; } } @@ -383,7 +430,7 @@ static void closed_evt(mrp_transport_t *t, int error, void *user_data) MRP_UNUSED(t); MRP_UNUSED(error); - mrp_log_error("server closed the connection"); + log_write("server closed the connection\n"); mrp_mainloop_quit(ctx->ml, 0); } @@ -406,14 +453,14 @@ static int connect_to_murphy(char *address, ctx_t *ctx) !mrp_msg_register_type(&asm_to_lib_descr) || !mrp_msg_register_type(&asm_to_lib_cb_descr) || !mrp_msg_register_type(&lib_to_asm_cb_descr)) { - mrp_log_error("Failed to register message types"); + log_write("Failed to register message types\n"); goto error; } alen = mrp_transport_resolve(NULL, address, &addr, sizeof(addr), &atype); if (alen <= 0) { - mrp_log_error("Error resolving transport address"); + log_write("Error resolving transport address\n"); goto error; } @@ -421,12 +468,12 @@ static int connect_to_murphy(char *address, ctx_t *ctx) MRP_TRANSPORT_MODE_CUSTOM | MRP_TRANSPORT_NONBLOCK); if (ctx->mt == NULL) { - mrp_log_error("Failed to create the transport"); + log_write("Failed to create the transport\n"); goto error; } if (!mrp_transport_connect(ctx->mt, &addr, alen)) { - mrp_log_error("Failed to connect the transport"); + log_write("Failed to connect the transport\n"); goto error; } @@ -473,10 +520,16 @@ int main (int argc, char **argv) ctx_t ctx; ctx.watched_files = NULL; +#if 0 + log_init("/tmp/asm-bridge-log"); +#else + logfile = NULL; +#endif + /* set up the signal handling */ if (asm_snd_msgid == -1 || asm_rcv_msgid == -1) { - mrp_log_error("failed to create the message queues\n"); + log_write("failed to create the message queues\n"); goto end; } @@ -485,10 +538,12 @@ int main (int argc, char **argv) ctx.snd_msgq = asm_snd_msgid; if (argc != 2 || strncmp(argv[1], "unxs", 4) != 0) { - mrp_log_error("Usage: asm-bridge "); + log_write("Usage: asm-bridge \n"); goto end; } + log_write("Started ASM bridge (%s)\n", argv[1]); + watches_conf.comp = mrp_string_comp; watches_conf.hash = mrp_string_hash; watches_conf.free = htbl_free_watches; @@ -530,7 +585,7 @@ int main (int argc, char **argv) mrp_mainloop_run(ctx.ml); - mrp_log_warning("shutting down asm-bridge"); + log_write("shutting down asm-bridge\n"); end: if (iow) @@ -549,6 +604,9 @@ end: msgctl(asm_snd_msgid, IPC_RMID, 0); msgctl(asm_rcv_msgid, IPC_RMID, 0); + msgctl(asm_cb_msgid, IPC_RMID, 0); + + log_close(); exit(0); } -- 2.7.4