This is just a proof of concept for me to see how the overall communication works. From this patch, I learnt a lot about the importances of callback, the tag struct etc. It's a nice start for me to dive into pulseaudio. :) However, there's still a lot to improve: 1. Add thread protection to log facilities. To make it simple at first, I haven't added that yet, but in real cases, different threads would call the log function, and if protection is not there, all would be messed up. 2. reduce the overhead of copying the data buffer. Now, `get_log_buffer' allocates a new buffer and pass it to tag struct. But this kind of operation can be reduced to keep the overhead at minimal. Signed-off-by: Deng Zhenrong <dzrongg at gmail.com> --- src/map-file | 1 + src/pulse/introspect.c | 34 +++++++++++++++++++++++ src/pulse/introspect.h | 3 ++ src/pulsecore/log.c | 58 +++++++++++++++++++++++++++++++++++++++ src/pulsecore/log.h | 2 + src/pulsecore/native-common.h | 1 + src/pulsecore/pdispatch.c | 1 + src/pulsecore/protocol-native.c | 26 +++++++++++++++++ src/utils/pactl.c | 14 +++++++++ 9 files changed, 140 insertions(+), 0 deletions(-) diff --git a/src/map-file b/src/map-file index 69cf25b..812875a 100644 --- a/src/map-file +++ b/src/map-file @@ -46,6 +46,7 @@ pa_context_get_protocol_version; pa_context_get_sample_info_by_index; pa_context_get_sample_info_by_name; pa_context_get_sample_info_list; +pa_context_get_log; pa_context_get_server; pa_context_get_server_info; pa_context_get_server_protocol_version; diff --git a/src/pulse/introspect.c b/src/pulse/introspect.c index 38a9d1c..2f2ef98 100644 --- a/src/pulse/introspect.c +++ b/src/pulse/introspect.c @@ -79,6 +79,40 @@ pa_operation* pa_context_stat(pa_context *c, pa_stat_info_cb_t cb, void *userdat return pa_context_send_simple_command(c, PA_COMMAND_STAT, context_stat_callback, (pa_operation_cb_t) cb, userdata); } +/*** Logs ***/ +static void context_get_log_callback(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata) { + pa_operation *o = userdata; + const char *p = NULL; + + pa_assert(pd); + pa_assert(o); + pa_assert(PA_REFCNT_VALUE(o) >= 1); + + if (!o->context) + goto finish; + + if (command != PA_COMMAND_REPLY) { + if (pa_context_handle_error(o->context, command, t, FALSE) < 0) + goto finish; + } else if (pa_tagstruct_gets(t, &p) < 0) { + pa_context_fail(o->context, PA_ERR_PROTOCOL); + goto finish; + } + + if (o->callback) { + pa_log_info_cb_t cb = (pa_log_info_cb_t) o->callback; + cb(o->context, p, o->userdata); + } + +finish: + pa_operation_done(o); + pa_operation_unref(o); +} + +pa_operation* pa_context_get_log(pa_context *c, pa_log_info_cb_t cb, void *userdata) { + return pa_context_send_simple_command(c, PA_COMMAND_GET_LOG, context_get_log_callback, (pa_operation_cb_t) cb, userdata); +} + /*** Server Info ***/ static void context_get_server_info_callback(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata) { diff --git a/src/pulse/introspect.h b/src/pulse/introspect.h index 224432c..e6e1577 100644 --- a/src/pulse/introspect.h +++ b/src/pulse/introspect.h @@ -629,6 +629,9 @@ pa_operation* pa_context_stat(pa_context *c, pa_stat_info_cb_t cb, void *userdat /** @} */ +typedef void (*pa_log_info_cb_t) (pa_context *c, const char *buffer, void *userdata); +pa_operation* pa_context_get_log(pa_context *c, pa_log_info_cb_t cb, void *userdata); + /** @{ \name Cached Samples */ /** Stores information about sample cache entries. Please note that this structure diff --git a/src/pulsecore/log.c b/src/pulsecore/log.c index 8eaef54..1a4dbf4 100644 --- a/src/pulsecore/log.c +++ b/src/pulsecore/log.c @@ -107,6 +107,55 @@ static void ident_destructor(void) { pa_xfree(ident); } +#define BUFFER_LENGTH (1024 * 1024) +static char log_buffer[BUFFER_LENGTH]; +static int log_start_index = 0; +static int log_end_index = 0; +static size_t log_used_length = 0; + +char *get_log_buffer() { + char *result = pa_xnew0(char, BUFFER_LENGTH+1); + memcpy(result, &log_buffer[log_start_index], log_used_length); + result[log_used_length] = '\0'; + + return result; +} + +static void write_to_circular_buffer(const char *p, size_t len) { + const char *base = p; + + while (len > 0) { + size_t first_chunk; + size_t min = len; + if (min > BUFFER_LENGTH) + min = BUFFER_LENGTH; + + first_chunk = BUFFER_LENGTH - log_end_index; + if (min <= first_chunk) { + // it can be put into the first part, don't need to wrap up. + memcpy(&log_buffer[log_end_index], base, min); + } else { + // copy the first chunk + memcpy(&log_buffer[log_end_index], base, first_chunk); + // copy the left data + memcpy(&log_buffer[0], base + first_chunk, min - first_chunk); + } + + log_end_index += min; + if (log_end_index >= BUFFER_LENGTH) { + log_end_index -= BUFFER_LENGTH; + } + log_used_length += min; + if (log_used_length >= BUFFER_LENGTH) { + log_start_index = log_end_index; + log_used_length = BUFFER_LENGTH; + } + + base += min; + len -= min; + } +} + void pa_log_set_level(pa_log_level_t l) { pa_assert(l < PA_LOG_LEVEL_MAX); @@ -358,6 +407,7 @@ void pa_log_levelv_meta( case PA_LOG_STDERR: { const char *prefix = "", *suffix = "", *grey = ""; + char metadata[256]; char *local_t; #ifndef OS_IS_WIN32 @@ -381,10 +431,18 @@ void pa_log_levelv_meta( if ((local_t = pa_utf8_to_locale(t))) t = local_t; + + pa_snprintf(metadata, sizeof(metadata), "\n%c %s %s", level_to_char[level], timestamp, location); + + // write metadata first and then t into circular buffer, as a first try, we write log to both log buffer and stderr. + write_to_circular_buffer(metadata, strlen(metadata)); + write_to_circular_buffer(t, strlen(t)); + if (_flags & PA_LOG_PRINT_LEVEL) fprintf(stderr, "%s%c: %s%s%s%s%s%s\n", timestamp, level_to_char[level], location, prefix, t, grey, pa_strempty(bt), suffix); else fprintf(stderr, "%s%s%s%s%s%s%s\n", timestamp, location, prefix, t, grey, pa_strempty(bt), suffix); + #ifdef OS_IS_WIN32 fflush(stderr); #endif diff --git a/src/pulsecore/log.h b/src/pulsecore/log.h index 8dd056b..21a599f 100644 --- a/src/pulsecore/log.h +++ b/src/pulsecore/log.h @@ -63,6 +63,8 @@ typedef enum pa_log_merge { PA_LOG_RESET } pa_log_merge_t; +char *get_log_buffer(); + /* Set an identification for the current daemon. Used when logging to syslog. */ void pa_log_set_ident(const char *p); diff --git a/src/pulsecore/native-common.h b/src/pulsecore/native-common.h index 5d1ba6a..34d4ccf 100644 --- a/src/pulsecore/native-common.h +++ b/src/pulsecore/native-common.h @@ -46,6 +46,7 @@ enum { PA_COMMAND_LOOKUP_SOURCE, PA_COMMAND_DRAIN_PLAYBACK_STREAM, PA_COMMAND_STAT, + PA_COMMAND_GET_LOG, PA_COMMAND_GET_PLAYBACK_LATENCY, PA_COMMAND_CREATE_UPLOAD_STREAM, PA_COMMAND_DELETE_UPLOAD_STREAM, diff --git a/src/pulsecore/pdispatch.c b/src/pulsecore/pdispatch.c index 9a9ef4e..ed88f73 100644 --- a/src/pulsecore/pdispatch.c +++ b/src/pulsecore/pdispatch.c @@ -64,6 +64,7 @@ static const char *command_names[PA_COMMAND_MAX] = { [PA_COMMAND_LOOKUP_SOURCE] = "LOOKUP_SOURCE", [PA_COMMAND_DRAIN_PLAYBACK_STREAM] = "DRAIN_PLAYBACK_STREAM", [PA_COMMAND_STAT] = "STAT", + [PA_COMMAND_GET_LOG] = "GET_LOG", [PA_COMMAND_GET_PLAYBACK_LATENCY] = "GET_PLAYBACK_LATENCY", [PA_COMMAND_CREATE_UPLOAD_STREAM] = "CREATE_UPLOAD_STREAM", [PA_COMMAND_DELETE_UPLOAD_STREAM] = "DELETE_UPLOAD_STREAM", diff --git a/src/pulsecore/protocol-native.c b/src/pulsecore/protocol-native.c index 41fc0a0..468d566 100644 --- a/src/pulsecore/protocol-native.c +++ b/src/pulsecore/protocol-native.c @@ -262,6 +262,7 @@ static void command_auth(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_ta static void command_set_client_name(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata); static void command_lookup(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata); static void command_stat(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata); +static void command_get_log(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata); static void command_get_playback_latency(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata); static void command_get_record_latency(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata); static void command_create_upload_stream(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata); @@ -309,6 +310,7 @@ static const pa_pdispatch_cb_t command_table[PA_COMMAND_MAX] = { [PA_COMMAND_LOOKUP_SINK] = command_lookup, [PA_COMMAND_LOOKUP_SOURCE] = command_lookup, [PA_COMMAND_STAT] = command_stat, + [PA_COMMAND_GET_LOG] = command_get_log, [PA_COMMAND_GET_PLAYBACK_LATENCY] = command_get_playback_latency, [PA_COMMAND_GET_RECORD_LATENCY] = command_get_record_latency, [PA_COMMAND_CREATE_UPLOAD_STREAM] = command_create_upload_stream, @@ -2786,6 +2788,30 @@ static void command_stat(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_ta pa_pstream_send_tagstruct(c->pstream, reply); } +static void command_get_log(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata) { + pa_native_connection *c = PA_NATIVE_CONNECTION(userdata); + pa_tagstruct *reply; + char *buffer; + + pa_native_connection_assert_ref(c); + pa_assert(t); + + if (!pa_tagstruct_eof(t)) { + protocol_error(c); + return; + } + + CHECK_VALIDITY(c->pstream, c->authorized, tag, PA_ERR_ACCESS); + + reply = reply_new(tag); + + buffer = get_log_buffer(); + pa_tagstruct_puts(reply, buffer); + pa_xfree(buffer); + + pa_pstream_send_tagstruct(c->pstream, reply); +} + static void command_get_playback_latency(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa_tagstruct *t, void *userdata) { pa_native_connection *c = PA_NATIVE_CONNECTION(userdata); pa_tagstruct *reply; diff --git a/src/utils/pactl.c b/src/utils/pactl.c index 05a1519..6a8d680 100644 --- a/src/utils/pactl.c +++ b/src/utils/pactl.c @@ -93,6 +93,7 @@ static enum { NONE, EXIT, STAT, + LOG, INFO, UPLOAD_SAMPLE, PLAY_SAMPLE, @@ -164,6 +165,12 @@ static void stat_callback(pa_context *c, const pa_stat_info *i, void *userdata) complete_action(); } +static void get_log_callback(pa_context *c, const char *buf, void *userdata) { + if (buf != NULL) + printf("%s\n", buf); + complete_action(); +} + static void get_server_info_callback(pa_context *c, const pa_server_info *i, void *useerdata) { char ss[PA_SAMPLE_SPEC_SNPRINT_MAX], cm[PA_CHANNEL_MAP_SNPRINT_MAX]; @@ -1081,6 +1088,10 @@ static void context_state_callback(pa_context *c, void *userdata) { break; actions++; + case LOG: + pa_operation_unref(pa_context_get_log(c, get_log_callback, NULL)); + break; + case INFO: pa_operation_unref(pa_context_get_server_info(c, get_server_info_callback, NULL)); break; @@ -1439,6 +1450,9 @@ int main(int argc, char *argv[]) { if (optind+1 < argc && pa_streq(argv[optind+1], "short")) short_list_format = TRUE; + } else if (pa_streq(argv[optind], "log")) { + action = LOG; + } else if (pa_streq(argv[optind], "info")) action = INFO; -- 1.7.6.5