[4095] in BarnOwl Developers
Re: [barnowl/barnowl] Defer failed log messages (#109)
daemon@ATHENA.MIT.EDU (Alex Dehnert)
Sat Aug 5 21:49:19 2017
Date: Sun, 06 Aug 2017 01:49:17 +0000 (UTC)
From: Alex Dehnert <notifications@github.com>
Reply-To: barnowl/barnowl <reply+004448c9bfd795878da6b5d87261712375e76ce8b0f3591c92cf00000001159e379c92a169ce009427d1@reply.github.com>
To: barnowl/barnowl <barnowl@noreply.github.com>
Cc: Subscribed <subscribed@noreply.github.com>
In-Reply-To: <barnowl/barnowl/pull/109@github.com>
----==_mimepart_5986759c9337f_5fb73fa578401c3c90888
Content-Type: text/plain;
charset=UTF-8
Content-Transfer-Encoding: 7bit
adehnert requested changes on this pull request.
> @@ -180,13 +226,108 @@ static void owl_log_entry_free(void *data)
}
}
+#if GLIB_CHECK_VERSION(2, 32, 0)
+#else
+static void owl_log_entry_free_gfunc(gpointer data, gpointer user_data)
+{
+ owl_log_entry_free(data);
+}
+#endif
+
+static void owl_log_file_error(owl_log_entry *msg, int ret)
I'd prefer this were called "errnum", which matches GLib and is a little clearer what it is. (I guess errno is taken by the global.)
> + owl_log_entry_free(data);
+}
+#endif
+
+static void owl_log_file_error(owl_log_entry *msg, int ret)
+{
+ owl_log_error("Unable to open file for logging: %s (file %s)",
+ g_strerror(ret),
+ msg->filename);
+}
+
+/* If we are deferring log messages, enqueue this entry for writing.
+ * Otherwise, try to write this log message, and, if it fails with
+ * EPERM, EACCES, or ETIMEDOUT, go into deferred logging mode and
+ * queue an admin message. If it fails with anything else, display an
+ * error message, but do not go into deferred logging mode. */
I *think* this means "and drop it on the floor", but clarifying that in the comment would be nice.
> + } else if (ret != 0) {
+ owl_log_file_error(msg, ret);
+ }
+ }
+}
+
+/* tries to write the deferred log entries */
+static void owl_log_write_deferred_entries(gpointer data)
+{
+ owl_log_entry *entry;
+ bool drop_failed_logs = *(bool *)data;
+ int ret;
+ int logged_message_count = 0;
+ bool all_succeeded = true;
+
+ defer_logs = false;
Is this racey? It's written and read from two functions -- are they the same thread? Jason says in person that they are, but it'd be good to add a comment about that.
> + /* Attempt to write the log entry. If it fails, re-queue the entry at
+ * the head of the queue. */
+ owl_log_eventually_write_entry(entry);
+ } else {
+ /* Attempt to write the log entry. If it fails, print an error message,
+ * drop the log, and keep going through the queue. */
+ ret = owl_log_try_write_entry(entry);
+ if (ret != 0) {
+ all_succeeded = false;
+ owl_log_file_error(entry, ret);
+ }
+ }
+ owl_log_entry_free(entry);
+ }
+ if (all_succeeded && logged_message_count > 0 && !defer_logs) {
+ owl_log_adminmsg("Logs have been flushed and logging has resumed.");
It would be nice to report how many logs got flushed.
> log_loop = g_main_loop_new(log_context, FALSE);
g_main_loop_run(log_loop);
return NULL;
}
-void owl_log_init(void)
+void owl_log_init(void)
:+1:
> +
+use BarnOwl::Timer;
+use Exporter;
+
+our @EXPORT_OK = qw();
+
+our %EXPORT_TAGS = (all => [@EXPORT_OK]);
+
+$BarnOwl::Hooks::startup->add("BarnOwl::DeferredLogging::_register_variables");
+
+sub _register_variables {
+ my $flush_logs_interval = -1;
+ my $flush_logs_timer;
+ BarnOwl::new_variable_full('flush-logs-interval',
+ {
+ default => -1,
I kinda wish we we could have a positive default (60 minutes? 360?), but I'm not sure how I feel about the "drop anything that fails for not-EACCES/EPERM/ETIMEDOUT" rule. I guess the prior rule was "drop anything that fails", so not so bad...?
> + BarnOwl::new_variable_full('flush-logs-interval',
+ {
+ default => -1,
+ summary => 'how often should logs be flushed, in minutes',
+ description => "If this is set to a positive value n, deferred logs \n"
+ . "are flushed every n minutes. If set to a negative or \n"
+ . "zero values, deferred logs are only flushed when the \n"
+ . "command :flush-logs is used.",
+ get_tostring => sub { "$flush_logs_interval" },
+ set_fromstring => sub {
+ die "Expected integer" unless $_[0] =~ /^-?[0-9]+$/;
+ $flush_logs_interval = 0 + $_[0];
+ $flush_logs_timer->stop if defined $flush_logs_timer;
+ undef $flush_logs_timer;
+ if ($flush_logs_interval > 0) {
+ $flush_logs_timer = BarnOwl::Timer->new({
I guess this is new_variable_full instead of new_variable_int because of the timer. It'd be good to note this in a comment, I think.
> +
+sub _register_variables {
+ my $flush_logs_interval = -1;
+ my $flush_logs_timer;
+ BarnOwl::new_variable_full('flush-logs-interval',
+ {
+ default => -1,
+ summary => 'how often should logs be flushed, in minutes',
+ description => "If this is set to a positive value n, deferred logs \n"
+ . "are flushed every n minutes. If set to a negative or \n"
+ . "zero values, deferred logs are only flushed when the \n"
+ . "command :flush-logs is used.",
+ get_tostring => sub { "$flush_logs_interval" },
+ set_fromstring => sub {
+ die "Expected integer" unless $_[0] =~ /^-?[0-9]+$/;
+ $flush_logs_interval = 0 + $_[0];
Is that seriously how one converts a string to an int in Perl? *sigh*
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/barnowl/barnowl/pull/109#pullrequestreview-54525291
----==_mimepart_5986759c9337f_5fb73fa578401c3c90888
Content-Type: text/html;
charset=UTF-8
Content-Transfer-Encoding: quoted-printable
<p><b>@adehnert</b> requested changes on this pull request.</p>
<hr>
<p>In <a href=3D"https://github.com/barnowl/barnowl/pull/109#discussion_r13=
1532257">logging.c</a>:</p>
<pre style=3D'color:#555'>> @@ -180,13 +226,108 @@ static void owl_log_e=
ntry_free(void *data)
}
}
=20
+#if GLIB_CHECK_VERSION(2, 32, 0)
+#else
+static void owl_log_entry_free_gfunc(gpointer data, gpointer user_data)
+{
+ owl_log_entry_free(data);
+}
+#endif
+
+static void owl_log_file_error(owl_log_entry *msg, int ret)
</pre>
<p>I'd prefer this were called "errnum", which matches GLib and is a little=
clearer what it is. (I guess errno is taken by the global.)</p>
<hr>
<p>In <a href=3D"https://github.com/barnowl/barnowl/pull/109#discussion_r13=
1532293">logging.c</a>:</p>
<pre style=3D'color:#555'>> + owl_log_entry_free(data);
+}
+#endif
+
+static void owl_log_file_error(owl_log_entry *msg, int ret)
+{
+ owl_log_error("Unable to open file for logging: %s (file %s)",
+ g_strerror(ret),
+ msg->filename);
+}
+
+/* If we are deferring log messages, enqueue this entry for writing.
+ * Otherwise, try to write this log message, and, if it fails with
+ * EPERM, EACCES, or ETIMEDOUT, go into deferred logging mode and
+ * queue an admin message. If it fails with anything else, display an
+ * error message, but do not go into deferred logging mode. */
</pre>
<p>I <em>think</em> this means "and drop it on the floor", but clarifying t=
hat in the comment would be nice.</p>
<hr>
<p>In <a href=3D"https://github.com/barnowl/barnowl/pull/109#discussion_r13=
1532473">logging.c</a>:</p>
<pre style=3D'color:#555'>> + } else if (ret !=3D 0) {
+ owl_log_file_error(msg, ret);
+ }
+ }
+}
+
+/* tries to write the deferred log entries */
+static void owl_log_write_deferred_entries(gpointer data)
+{
+ owl_log_entry *entry;
+ bool drop_failed_logs =3D *(bool *)data;
+ int ret;
+ int logged_message_count =3D 0;
+ bool all_succeeded =3D true;
+
+ defer_logs =3D false;
</pre>
<p>Is this racey? It's written and read from two functions -- are they the =
same thread? Jason says in person that they are, but it'd be good to add a =
comment about that.</p>
<hr>
<p>In <a href=3D"https://github.com/barnowl/barnowl/pull/109#discussion_r13=
1532562">logging.c</a>:</p>
<pre style=3D'color:#555'>> + /* Attempt to write the log entry. I=
f it fails, re-queue the entry at
+ * the head of the queue. */
+ owl_log_eventually_write_entry(entry);
+ } else {
+ /* Attempt to write the log entry. If it fails, print an error messa=
ge,
+ * drop the log, and keep going through the queue. */
+ ret =3D owl_log_try_write_entry(entry);
+ if (ret !=3D 0) {
+ all_succeeded =3D false;
+ owl_log_file_error(entry, ret);
+ }
+ }
+ owl_log_entry_free(entry);
+ }
+ if (all_succeeded && logged_message_count > 0 && !def=
er_logs) {
+ owl_log_adminmsg("Logs have been flushed and logging has resumed.=
");
</pre>
<p>It would be nice to report how many logs got flushed.</p>
<hr>
<p>In <a href=3D"https://github.com/barnowl/barnowl/pull/109#discussion_r13=
1532615">logging.c</a>:</p>
<pre style=3D'color:#555'>> log_loop =3D g_main_loop_new(log_context,=
FALSE);
g_main_loop_run(log_loop);
return NULL;
}
=20
-void owl_log_init(void)=20
+void owl_log_init(void)
</pre>
<p><g-emoji alias=3D"+1" fallback-src=3D"https://assets-cdn.github.com/imag=
es/icons/emoji/unicode/1f44d.png" ios-version=3D"6.0">=F0=9F=91=8D</g-emoji=
></p>
<hr>
<p>In <a href=3D"https://github.com/barnowl/barnowl/pull/109#discussion_r13=
1532707">perl/lib/BarnOwl/DeferredLogging.pm</a>:</p>
<pre style=3D'color:#555'>> +
+use BarnOwl::Timer;
+use Exporter;
+
+our @EXPORT_OK =3D qw();
+
+our %EXPORT_TAGS =3D (all =3D> [@EXPORT_OK]);
+
+$BarnOwl::Hooks::startup->add("BarnOwl::DeferredLogging::_register=
_variables");
+
+sub _register_variables {
+ my $flush_logs_interval =3D -1;
+ my $flush_logs_timer;
+ BarnOwl::new_variable_full('flush-logs-interval',
+ {
+ default =3D> -1,
</pre>
<p>I kinda wish we we could have a positive default (60 minutes? 360?), but=
I'm not sure how I feel about the "drop anything that fails for not-EACCES=
/EPERM/ETIMEDOUT" rule. I guess the prior rule was "drop anything that fail=
s", so not so bad...?</p>
<hr>
<p>In <a href=3D"https://github.com/barnowl/barnowl/pull/109#discussion_r13=
1532750">perl/lib/BarnOwl/DeferredLogging.pm</a>:</p>
<pre style=3D'color:#555'>> + BarnOwl::new_variable_full('flush-l=
ogs-interval',
+ {
+ default =3D> -1,
+ summary =3D> 'how often should logs be flushed, =
in minutes',
+ description =3D> "If this is set to a positive valu=
e n, deferred logs \n"
+ . "are flushed every n minutes. If set t=
o a negative or \n"
+ . "zero values, deferred logs are only fl=
ushed when the \n"
+ . "command :flush-logs is used.",
+ get_tostring =3D> sub { "$flush_logs_interval" =
},
+ set_fromstring =3D> sub {
+ die "Expected integer" unless $_[0] =3D~ /^-?[0-=
9]+$/;
+ $flush_logs_interval =3D 0 + $_[0];
+ $flush_logs_timer->stop if defined $flush_logs_timer;
+ undef $flush_logs_timer;
+ if ($flush_logs_interval > 0) {
+ $flush_logs_timer =3D BarnOwl::Timer->new({
</pre>
<p>I guess this is new_variable_full instead of new_variable_int because of=
the timer. It'd be good to note this in a comment, I think.</p>
<hr>
<p>In <a href=3D"https://github.com/barnowl/barnowl/pull/109#discussion_r13=
1532755">perl/lib/BarnOwl/DeferredLogging.pm</a>:</p>
<pre style=3D'color:#555'>> +
+sub _register_variables {
+ my $flush_logs_interval =3D -1;
+ my $flush_logs_timer;
+ BarnOwl::new_variable_full('flush-logs-interval',
+ {
+ default =3D> -1,
+ summary =3D> 'how often should logs be flushed, =
in minutes',
+ description =3D> "If this is set to a positive valu=
e n, deferred logs \n"
+ . "are flushed every n minutes. If set t=
o a negative or \n"
+ . "zero values, deferred logs are only fl=
ushed when the \n"
+ . "command :flush-logs is used.",
+ get_tostring =3D> sub { "$flush_logs_interval" =
},
+ set_fromstring =3D> sub {
+ die "Expected integer" unless $_[0] =3D~ /^-?[0-=
9]+$/;
+ $flush_logs_interval =3D 0 + $_[0];
</pre>
<p>Is that seriously how one converts a string to an int in Perl? <em>sigh<=
/em></p>
<p style=3D"font-size:small;-webkit-text-size-adjust:none;color:#666;">&mda=
sh;<br />You are receiving this because you are subscribed to this thread.<=
br />Reply to this email directly, <a href=3D"https://github.com/barnowl/ba=
rnowl/pull/109#pullrequestreview-54525291">view it on GitHub</a>, or <a hre=
f=3D"https://github.com/notifications/unsubscribe-auth/AERIyVkN6gIl5vNHPFTH=
ShD-jzQRostiks5sVRucgaJpZM4AWArI">mute the thread</a>.<img alt=3D"" height=
=3D"1" src=3D"https://github.com/notifications/beacon/AERIyRYgUFYKb9LoRfhf2=
RbV89gI708Fks5sVRucgaJpZM4AWArI.gif" width=3D"1" /></p>
<div itemscope itemtype=3D"http://schema.org/EmailMessage">
<div itemprop=3D"action" itemscope itemtype=3D"http://schema.org/ViewAction=
">
<link itemprop=3D"url" href=3D"https://github.com/barnowl/barnowl/pull/10=
9#pullrequestreview-54525291"></link>
<meta itemprop=3D"name" content=3D"View Pull Request"></meta>
</div>
<meta itemprop=3D"description" content=3D"View this Pull Request on GitHub"=
></meta>
</div>
<script type=3D"application/json" data-scope=3D"inboxmarkup">{"api_version"=
:"1.0","publisher":{"api_key":"05dde50f1d1a384dd78767c55493e4bb","name":"Gi=
tHub"},"entity":{"external_key":"github/barnowl/barnowl","title":"barnowl/b=
arnowl","subtitle":"GitHub repository","main_image_url":"https://cloud.gith=
ubusercontent.com/assets/143418/17495839/a5054eac-5d88-11e6-95fc-7290892c7b=
b5.png","avatar_image_url":"https://cloud.githubusercontent.com/assets/1434=
18/15842166/7c72db34-2c0b-11e6-9aed-b52498112777.png","action":{"name":"Ope=
n in GitHub","url":"https://github.com/barnowl/barnowl"}},"updates":{"snipp=
ets":[{"icon":"PERSON","message":"@adehnert requested changes on #109"}],"a=
ction":{"name":"View Pull Request","url":"https://github.com/barnowl/barnow=
l/pull/109#pullrequestreview-54525291"}}}</script>=
----==_mimepart_5986759c9337f_5fb73fa578401c3c90888--
