GNOME Bugzilla – Bug 721764
souphttpsrc: Add ability to do HTTP session logging
Last modified: 2014-02-11 21:38:20 UTC
Created attachment 265630 [details] [review] Add ability to do HTTP session logging While working on another soup related issue I noticed libsoup provides API facilities to do HTTP session logging. As I have found myself in need of such a feature I figured it wouldn't hurt to add this to our soup elements. I'm initially proposing the following (quite preliminary) patch to gather some feedback but if deemed useful I can move it out of the src element and make it a .h/.c util-like set for both soup elements to use. The change basically adds an http-logging-level prop, if set and > 0 it will instruct soup to dump HTTP request&response lines, full headers and full body sections for levels 1,2 and 3 respectively. A session dump will be added to the normal logs and looks like this (for a request/response lines (M) & HEADERS (H) one): HTTP_SESSION(M): > GET /stream.webm HTTP/1.1 HTTP_SESSION(M): > Soup-Debug-Timestamp: 1389145737 HTTP_SESSION(M): > Soup-Debug: SoupSessionAsync 1 (0x18e9240), SoupMessage 1 (0x188d5c0), SoupSocket 1 (0x16d5640) HTTP_SESSION(H): > Host: xxx.mooo.com:8000 HTTP_SESSION(H): > Connection: close HTTP_SESSION(H): > User-Agent: GStreamer souphttpsrc libsoup/2.44.1 HTTP_SESSION(M): HTTP_SESSION(M): < HTTP/1.0 200 OK HTTP_SESSION(M): < Soup-Debug-Timestamp: 1389145777 HTTP_SESSION(M): < Soup-Debug: SoupMessage 1 (0x188d5c0) HTTP_SESSION(H): < Server: Icecast 2.3.99.3 HTTP_SESSION(H): < Date: Wed, 08 Jan 2014 02:42:29 GMT HTTP_SESSION(H): < Content-Type: video/webm HTTP_SESSION(H): < Cache-Control: no-cache HTTP_SESSION(H): < Expires: Mon, 26 Jul 1997 05:00:00 GMT HTTP_SESSION(H): < Pragma: no-cache HTTP_SESSION(H): < icy-description: lolo HTTP_SESSION(H): < icy-name: lala HTTP_SESSION(H): < icy-pub: 0 HTTP_SESSION(M): HTTP_SESSION(M): > GET /stream.webm HTTP/1.1 HTTP_SESSION(M): > Soup-Debug-Timestamp: 1389145778 HTTP_SESSION(M): > Soup-Debug: SoupSessionAsync 1 (0x18e9240), SoupMessage 2 (0x188d6b0), SoupSocket 2 (0x16d5700) HTTP_SESSION(H): > Host: xxx.mooo.com:8000 HTTP_SESSION(H): > Connection: close HTTP_SESSION(H): > Range: bytes=1662974- HTTP_SESSION(H): > User-Agent: GStreamer souphttpsrc libsoup/2.44.1 HTTP_SESSION(M): HTTP_SESSION(M): < HTTP/1.0 1 Cancelled HTTP_SESSION(M): < Soup-Debug-Timestamp: 1389145778 HTTP_SESSION(M): < Soup-Debug: SoupMessage 2 (0x188d6b0) HTTP_SESSION(H): < Server: Icecast 2.3.99.3 HTTP_SESSION(H): < Date: Wed, 08 Jan 2014 02:43:10 GMT HTTP_SESSION(H): < Content-Type: video/webm HTTP_SESSION(H): < Cache-Control: no-cache HTTP_SESSION(H): < Expires: Mon, 26 Jul 1997 05:00:00 GMT HTTP_SESSION(H): < Pragma: no-cache HTTP_SESSION(H): < icy-description: lolo HTTP_SESSION(H): < icy-name: lala HTTP_SESSION(H): < icy-pub: 0 HTTP_SESSION(M): ( < and > for inbound & outbound respectively) Some questions: Would a new log category be needed? I'm using GST_DEBUG. If user goes GST_LOG_LEVEL < 4 these messages are going to be ignored. Does this sound like an acceptable compromise? What if the log subsystem gets disabled at build time, would it be OK to add an ifdefed fallback to printf logging for the log printer callback?
Review of attachment 265630 [details] [review]: ::: ext/soup/gstsouphttpsrc.c @@ +256,3 @@ DEFAULT_IRADIO_MODE, G_PARAM_READWRITE | G_PARAM_STATIC_STRINGS)); + g_object_class_install_property (gobject_class, PROP_SOUP_LOG_LEVEL, + g_param_spec_uint ("http-log-level", "http-log-level", Use the SoupLoggerLogLevel enum here and make it an enum property @@ +381,3 @@ + break; + } + return SOUP_LOGGER_LOG_NONE; No need to translate levels then :) @@ +401,3 @@ + default: + c = '?'; + g_assert_not_reached (); Let the default be the number maybe and don't assert. Who knows what libsoup will add here later @@ +415,3 @@ + gchar c; + c = gst_soup_http_log_make_level_tag (level); + GST_DEBUG ("HTTP_SESSION(%c): %c %s", c, direction, data); MEMDUMP or TRACE level IMHO, not DEBUG @@ +419,3 @@ + +static void +gst_soup_http_log_setup (GstSoupHTTPSrc * src) This function looks weird in general... see next comment @@ +826,3 @@ + soup_session_remove_feature (src->session, + SOUP_SESSION_FEATURE (src->http_logger)); + src->http_logger = NULL; Shouldn't this just be done at the place where the session object is destroyed? Add the logger feature once when the session is created, and destroy once when it's destroyed
Oh and also only add the logger feature to the session if the soup debug category has a level >= DEBUG (or MEMDUMP or TRACE). You don't want to add it always.
Created attachment 265810 [details] [review] proposed fix Addressed most of your comments. Please review.
Review of attachment 265810 [details] [review]: ::: ext/soup/gstsouphttpsrc.c @@ +715,3 @@ + + /* Setup logging */ + gst_soup_util_log_setup (src->logger, src->log_level, src->session, src); This does not make sense. You pass a logger here (which is never set to anything), but in that function create one and set it on the session. Maybe just make that > gst_soup_util_log_setup(session, level, src) if removing is not necessary (I don't think it is, the session will free the object when it goes aways). Or > src->logger = gst_soup_util_create_logger (level, src); > soup_session_add_feature(session, src->logger); ::: ext/soup/gstsouputils.c @@ +31,3 @@ +gst_soup_util_init (void) +{ + GST_DEBUG_CATEGORY_INIT (gst_soup_utils, "gstsouputils", 0, "Soup utils"); Or just do that in plugin_init() and make the debug category extern. No need for another function here @@ +50,3 @@ + break; + default: + GST_WARNING ("Don't recognize soup logger level: %d", level); GST_WARNING_OBJECT(), but not needed at all imho. Just replace the ? with the level number :) @@ +84,3 @@ + + if (logger) { + GST_WARNING ("We already have a logger. Not attaching another one"); All these checks should be a g_return_if_fail() IMHO. They are programming errors @@ +88,3 @@ + } + + if (gst_debug_category_get_threshold (GST_CAT_DEFAULT) No, check for the category you're using here @@ +97,3 @@ + /* Create a new logger and set body_size_limit to -1 (no limit) */ + logger = soup_logger_new (level, -1); + soup_logger_set_printer (logger, gst_soup_util_log_printer_cb, element, NULL); ..., gst_object_ref(element), (GDestroyNotify) gst_object_unref);
(In reply to comment #4) > Review of attachment 265810 [details] [review]: > > [..] > ::: ext/soup/gstsouputils.c > @@ +31,3 @@ > +gst_soup_util_init (void) > +{ > + GST_DEBUG_CATEGORY_INIT (gst_soup_utils, "gstsouputils", 0, "Soup utils"); > > Or just do that in plugin_init() and make the debug category extern. No need > for another function here Do I understand correctly that would require the calling code to be aware of souputil's debug category name? What are we gaining really?. I'm OK with taking it out though. > > @@ +50,3 @@ > + break; > + default: > + GST_WARNING ("Don't recognize soup logger level: %d", level); > > GST_WARNING_OBJECT(), but not needed at all imho. Just replace the ? with the > level number :) Agreed, thanks. > > @@ +84,3 @@ > + > + if (logger) { > + GST_WARNING ("We already have a logger. Not attaching another one"); > > All these checks should be a g_return_if_fail() IMHO. They are programming > errors Code then will misbehave if G_DISABLE_CHECKS was set for glib?. Now (!level) is being read from a writable user facing prop, I'm guessing you didn't meant to include that one in your "they"? About the checking for GST_CAT_DEFAULT, that macro is expanding to gst_soup_utils on that file already. What's wrong with it? Will post an updated patch once these questions are resolved. Thanks a lot for your time and comments Sebastian.
(In reply to comment #5) > (In reply to comment #4) > > Review of attachment 265810 [details] [review] [details]: > > > > [..] > > ::: ext/soup/gstsouputils.c > > @@ +31,3 @@ > > +gst_soup_util_init (void) > > +{ > > + GST_DEBUG_CATEGORY_INIT (gst_soup_utils, "gstsouputils", 0, "Soup utils"); > > > > Or just do that in plugin_init() and make the debug category extern. No need > > for another function here > > Do I understand correctly that would require the calling code to > be aware of souputil's debug category name? What are we gaining > really?. I'm OK with taking it out though. GST_DEBUG_CATEGORY_EXTERN(gst_soup_utils) in the utils.c GST_DEBUG_CATEGORY(gst_soup_utils) in plugin.c GST_DEBUG_CATEGORY_INIT(gst_soup_utils) in plugin.c That's three lines vs. another function that needs to be called from two places and also would need some locking for thread safety :) > > @@ +84,3 @@ > > + > > + if (logger) { > > + GST_WARNING ("We already have a logger. Not attaching another one"); > > > > All these checks should be a g_return_if_fail() IMHO. They are programming > > errors > > Code then will misbehave if G_DISABLE_CHECKS > was set for glib?. Now (!level) is being read from > a writable user facing prop, I'm guessing you didn't > meant to include that one in your "they"? I did, setting the GObject property to another value will cause a g_critical() and is also considered a programming error. Adding a g_return_if_fail() for that seems ok. > About the checking for GST_CAT_DEFAULT, that macro is > expanding to gst_soup_utils on that file already. What's > wrong with it? Nothing, I forgot that you defined it to something sensible above :)
(In reply to comment #6) > [...] > GST_DEBUG_CATEGORY_EXTERN(gst_soup_utils) in the utils.c > GST_DEBUG_CATEGORY(gst_soup_utils) in plugin.c > GST_DEBUG_CATEGORY_INIT(gst_soup_utils) in plugin.c > > That's three lines vs. another function that needs to be called from two places > and also would need some locking for thread safety :) Oh. If you put it that way I can't possibly not agree ;) > [..] > > Code then will misbehave if G_DISABLE_CHECKS > > was set for glib?. Now (!level) is being read from > > a writable user facing prop, I'm guessing you didn't > > meant to include that one in your "they"? > > I did, setting the GObject property to another value will cause a g_critical() > and is also considered a programming error. Adding a g_return_if_fail() for > that seems ok. But 0 is not an invalid prop value. I just don't want to attach a logger for GST_SOUP_LOGGER_NONE so the g_return_if_fail() wont do any good but harm if G_DISABLE_CHECKS. Same for !session and logger. > > About the checking for GST_CAT_DEFAULT, that macro is > > expanding to gst_soup_utils on that file already. What's > > wrong with it? > > Nothing, I forgot that you defined it to something sensible above :) Cool ;) Thanks again. Working on a new version, should be posting it shortly.
(In reply to comment #7) > > > Code then will misbehave if G_DISABLE_CHECKS > > > was set for glib?. Now (!level) is being read from > > > a writable user facing prop, I'm guessing you didn't > > > meant to include that one in your "they"? > > > > I did, setting the GObject property to another value will cause a g_critical() > > and is also considered a programming error. Adding a g_return_if_fail() for > > that seems ok. > > But 0 is not an invalid prop value. I just don't want > to attach a logger for GST_SOUP_LOGGER_NONE so the > g_return_if_fail() wont do any good but harm if > G_DISABLE_CHECKS. Same for !session and logger. Oh right, for 0 you can do a normal if indeed :) All the others are programming errors though
(In reply to comment #8) > [..] > Oh right, for 0 you can do a normal if indeed :) All the others are programming > errors though Yup, but then with G_DISABLE_CHECKS I will end up attaching a logger to an nonexistent session, which might lead to a normal error but be a programming error on the lib itself. I will go with the g_return_if_fail() for (logger) and leave the others untouched if you are cool with it. Thanks again.
(In reply to comment #9) > [..] > I will go with the g_return_if_fail() for (logger) and leave > the others untouched if you are cool with it. Actually no, going g_return_if_ fail(!logger) would be bad with G_DISABLED_CHECKS too, for the very same reasons. So I will like to keep them all the way they are.
(In reply to comment #10) > (In reply to comment #9) > > [..] > > I will go with the g_return_if_fail() for (logger) and leave > > the others untouched if you are cool with it. > > Actually no, going g_return_if_ fail(!logger) would be bad with > G_DISABLED_CHECKS too, for the very same reasons. So I will > like to keep them all the way they are. Ended up dropping the logger param there anyway :)
Created attachment 265869 [details] [review] New version
Review of attachment 265869 [details] [review]: ::: ext/soup/gstsoup.c @@ +39,3 @@ gst_element_register (plugin, "souphttpclientsink", GST_RANK_NONE, GST_TYPE_SOUP_HTTP_CLIENT_SINK); + GST_DEBUG_CATEGORY_INIT (gst_soup_utils, "gstsouputils", 0, "Soup utils"); gstsouputils -> souputils. We don't put the gst prefix there anywhere else ::: ext/soup/gstsouphttpsrc.c @@ +248,3 @@ DEFAULT_IRADIO_MODE, G_PARAM_READWRITE | G_PARAM_STATIC_STRINGS)); + g_object_class_install_property (gobject_class, PROP_SOUP_LOG_LEVEL, + g_param_spec_enum ("http-log-level", "http-log-level", The second string should be "HTTP Log Level" or something similar @@ +713,3 @@ + + /* Setup logging */ + gst_soup_util_log_setup (src->log_level, src->session, src); Having the session as first parameter seems more natural but ok ;) ::: ext/soup/gstsouputils.c @@ +66,3 @@ +void +gst_soup_util_log_setup (SoupLoggerLogLevel level, SoupSession * session, + gpointer element) Make that a GstElement * @@ +77,3 @@ + + if (!session) { + GST_WARNING_OBJECT (who, "Have no session. Can't attach a logger"); This seriously needs a g_return_if_fail() as it must not happen. Same goes for !element @@ +84,3 @@ + < GST_LEVEL_TRACE) { + GST_WARNING ("Not setting up HTTP session logger. " + "Need at least GST_LEVEL_TRACE"); Not a warning @@ +91,3 @@ + * more than once (not meant to do so). Session + * will need to be checked for an already existant + * logger to drop it first */ Not necessarily, maybe you want different loggers with different printers.
(In reply to comment #13) > @@ +77,3 @@ > + > + if (!session) { > + GST_WARNING_OBJECT (who, "Have no session. Can't attach a logger"); > > This seriously needs a g_return_if_fail() as it must not happen. Same goes for > !element Should just be a g_assert() if it's a concern. g_return_*() is for public API. Looking at the callers of this function, it seems like we'll crash much earlier if session is NULL.
Created attachment 265942 [details] [review] latest incarnation
Created attachment 265967 [details] [review] Add the session logger to souphttpclientsink too Building on the previous patch. This ones adds the session logger to souphttpclientsink too
Created attachment 266190 [details] [review] Drop custom header printing debug func Building on the previous ones. This patch drops a custom debug printing func that was being called once per header line for inbound and outbound headers. Same functionality can be obtained now with\ http-log-level > 1, saving quite a few function calls\ if HTTP session dump's are not explicitly requested.
Created attachment 266191 [details] [review] Add the session logger to souphttpclientsink too Added missing bug# URL
Created attachment 266192 [details] [review] Drop custom header printing debug func Added missing bug# URL
Comment on attachment 266192 [details] [review] Drop custom header printing debug func Please squash that into the souphttpsrc patch where you add the debug thing
Review of attachment 265942 [details] [review]: Squash in the removal of the custom logging ::: ext/soup/gstsouphttpsrc.c @@ +247,3 @@ "metadata interleaved with the actual stream data)", DEFAULT_IRADIO_MODE, G_PARAM_READWRITE | G_PARAM_STATIC_STRINGS)); + g_object_class_install_property (gobject_class, PROP_SOUP_LOG_LEVEL, This should get some gtk-doc chunk with a Since: 1.4 ::: ext/soup/gstsouputils.c @@ +47,3 @@ + * log level to SoupLoggerLogLevel and it should be added + * as a case */ + c = level; Erm, no. You must make a printable char out of that :) level + '0' maybe, that will just do weird things if level is larger than 9.
Review of attachment 266191 [details] [review]: ::: ext/soup/gstsouphttpclientsink.c @@ +172,3 @@ g_param_spec_boxed ("cookies", "Cookies", "HTTP request cookies", G_TYPE_STRV, G_PARAM_READWRITE | G_PARAM_STATIC_STRINGS)); + g_object_class_install_property (gobject_class, PROP_SOUP_LOG_LEVEL, gtk-doc chunk with Since: 1.4 missing here
Created attachment 266270 [details] [review] Add ability to do HTTP session logging Thanks for your comments Sebastian. Should be all good now
Created attachment 266271 [details] [review] Add the session logger to souphttpclientsink too
Sebastian. Any further comments on these two?
Review of attachment 266270 [details] [review]: ::: ext/soup/gstsouphttpsrc.h @@ +24,2 @@ #include <libsoup/soup.h> +#include "gstsouputils.h" No need for the header here, only needed in the .c file ::: ext/soup/gstsouputils.c @@ +50,3 @@ + * log level to SoupLoggerLogLevel and it should be added + * as a case */ + c = level + '0'; This will break in interesting ways for too high levels. Maybe add an assertion here if level is too large, or use multiple characters. Or get the SoupLoggerLogLevel nick from the GEnum and just always use that
Review of attachment 266271 [details] [review]: Looks ok, but just squash that into the other patch
(In reply to comment #26) > Review of attachment 266270 [details] [review]: > > ::: ext/soup/gstsouphttpsrc.h > @@ +24,2 @@ > #include <libsoup/soup.h> > +#include "gstsouputils.h" > > No need for the header here, only needed in the .c file Leftover from a previous incarnation. Thanks for pointing it out. > ::: ext/soup/gstsouputils.c > @@ +50,3 @@ > + * log level to SoupLoggerLogLevel and it should be added > + * as a case */ > + c = level + '0'; > > This will break in interesting ways for too high levels. Maybe add an assertion > here if level is too large, or use multiple characters. Or get the > SoupLoggerLogLevel nick from the GEnum and just always use that There's already an if (G_UNLIKELY (level > 9)) return '?' on top of the switch to avoid that case. You might have missed it. Thanks for your review! Updated patch attached.
Created attachment 268419 [details] [review] Add ability to do HTTP session logging
Review of attachment 268419 [details] [review]: I missed that indeed :) Go ahead
Great. Done. Thanks for taking a look.