Bug#916230: Svlogd: log files named as `timestamp.u' even if there is no processor in place

classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|

Bug#916230: Svlogd: log files named as `timestamp.u' even if there is no processor in place

Lorenzo Puliti
Package: runit
Version: 2.1.2-19
Severity: normal

Hi Dmitry,

I have several log directories with more than 10 log files.
This is true when there are no config files and also when there is
a config file that sets `num' to 10.
The patch for #878476 (Fix spin lock on systems with poor clock) excluded
`.u' files from being deleted, and this fix highlighted that svlogd is
naming some or all log files as `timestamp.u' instead of `timestamp.s'.
I have no `processor' in place so this looks wrong to me.
Also, with a mix of `.t' and `.u' log files the number of old log
files is no longed guaranteed to be equal to `num'.

Some example below

# ls /var/log/socklog/main/
@400000005bec9d4312f06574.s  @400000005becbdb61a29ab84.s  @400000005bfb1d87038ba954.s  config
@400000005beca56327c6e25c.s  @400000005becc5d20d12bbac.s  @400000005c04f9792a66167c.u  current
@400000005becad7d096ee8cc.s  @400000005bf08a8011444bb4.s  @400000005c05672f19f2cca4.u  lock
@400000005becb59a286cceec.s  @400000005bf1e6aa28b2ffac.u  @400000005c0c14131dcfcc3c.u

# cat /var/log/socklog/main/config
s999999
n10

# ls /var/log/git-daemon/
@400000005b998548043f1ad4.u  @400000005bec24580f89227c.u  @400000005c0c14131d51beb4.u
@400000005bd6c9511b69cca4.u  @400000005bf1e6aa2881d9a4.u  current
@400000005be9f5cb053c62ac.u  @400000005c05672f1ad020cc.u  lock

#ls /var/log/openntpd/
@400000005b998548032ffc94.u  @400000005bf83e0606a08a74.s  @400000005c07cc2238359084.s
@400000005bd6c9511c410a34.u  @400000005bfd27a1004150b4.s  @400000005c0be372278ac3bc.s
@400000005be9f5cb03eb2e74.u  @400000005bffd5160718b814.s  @400000005c0c14131d8716f4.u
@400000005bec24580dc9abb4.u  @400000005c02d1022e67248c.s  @400000005c0fa55f0ec476d4.s
@400000005bf03e4023305e94.s  @400000005c032bcb2c921e3c.s  current
@400000005bf1e6aa287041bc.u  @400000005c04f9792a5447e4.u  lock
@400000005bf3fbac120daa7c.s  @400000005c05672f1990edf4.u

Am I missing something about the `processor' thing?


-- System Information:
Debian Release: buster/sid
  APT prefers unstable
  APT policy: (500, 'unstable')
Architecture: amd64 (x86_64)

Kernel: Linux 4.18.0-1-amd64 (SMP w/4 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE=en_US:en (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: runit (via /run/runit.stopit)

Versions of packages runit depends on:
ii  libc6         2.28-2
ii  runit-helper  2.7.3

Versions of packages runit recommends:
ii  runit-init  2.1.2-19

runit suggests no packages.

-- Configuration Files:
/etc/runit/3 changed [not included]

-- no debconf information

Reply | Threaded
Open this post in threaded view
|

Bug#916230: Svlogd: log files named as `timestamp.u' even if there is no processor in place

Dmitry Bogatov-3

control: tags -1 confirmed

[2018-12-11 18:51] Lorenzo Puliti <[hidden email]>

> Package: runit
> Version: 2.1.2-19
> Severity: normal
>
> Hi Dmitry,
>
> I have several log directories with more than 10 log files.
> This is true when there are no config files and also when there is
> a config file that sets `num' to 10.
> The patch for #878476 (Fix spin lock on systems with poor clock) excluded
> `.u' files from being deleted, and this fix highlighted that svlogd is
> naming some or all log files as `timestamp.u' instead of `timestamp.s'.
> I have no `processor' in place so this looks wrong to me.
> Also, with a mix of `.t' and `.u' log files the number of old log
> files is no longed guaranteed to be equal to `num'.

True. According to manpage, .u files should not appear if there is no
preprocessor specified.

I managed to reproduce bug. Seems that .u file appears when svlogd is
restarted and there is some .s files, but not always. I plan to debug
it this weekend.

Thank you for report. If you have some ideas, how to reproduce bug
more reliable, it would be great!

Reply | Threaded
Open this post in threaded view
|

Bug#916230: Svlogd: log files named as `timestamp.u' even if there is no processor in place

Dmitry Bogatov-3

[2018-12-12 19:39] Dmitry Bogatov <[hidden email]>
> I managed to reproduce bug. Seems that .u file appears when svlogd is
> restarted and there is some .s files, but not always. I plan to debug
> it this weekend.
>
> Thank you for report. If you have some ideas, how to reproduce bug
> more reliable, it would be great!

Offending .u file is created by rename(2) call at line 532, in
logdir_open() function. It happens, when 'current' file exists,
non-executable and non-empty.

Well, this is quite normal state of affairs. When `svlogd' is running,
`current' file is getting appended, when its size reaches `ld->sizemax'
(or something like this), it gets renames to @timestamp, and new
`current' is created.

So, if I interrupt `svlogd' at any time, but just after rotation, I
will get this leftover .u file. I am not perfectly sure, but seems that
`struct logdir` has `size' field, that means current size of log file.

I believe following patch would solve current issue. But wouldn't
it cause another problems? There must be reason, why this logic was
implemented. Gerrit, some input, please?

diff --git a/runit-2.1.2/src/svlogd.c b/runit-2.1.2/src/svlogd.c
index fab8441..3f8ead4 100644
--- a/runit-2.1.2/src/svlogd.c
+++ b/runit-2.1.2/src/svlogd.c
@@ -521,20 +521,7 @@ unsigned int logdir_open(struct logdir *ld, const char *fn) {
 
   /* open current */
   if ((i =stat("current", &st)) != -1) {
-    if (st.st_size && ! (st.st_mode & S_IXUSR)) {
-      ld->fnsave[25] ='.'; ld->fnsave[26] ='u'; ld->fnsave[27] =0;
-      do {
-        taia_now(&now);
-        fmt_taia(ld->fnsave, &now);
-        errno =0;
-      } while ((stat(ld->fnsave, &st) != -1) || (errno != error_noent));
-      while (rename("current", ld->fnsave) == -1)
-        pause2("unable to rename current", ld->name);
-      rmoldest(ld);
-      i =-1;
-    }
-    else
-      ld->size =st.st_size;
+    ld->size =st.st_size;
   }
   else
     if (errno != error_noent) {

Reply | Threaded
Open this post in threaded view
|

Bug#916230: Svlogd: log files named as `timestamp.u' even if there is no processor in place

Gerrit Pape-2
Hi Dmitry,

I'm sorry, can't give you any input, I'm busy with different things
these days.  But there're people around knowing the runit programs and
code, you can try to contact them through the mailing list
<[hidden email]> .

Best Regards, Gerrit.


On Mon, Dec 17, 2018 at 02:54:43PM +0000, Dmitry Bogatov wrote:

>
> [2018-12-12 19:39] Dmitry Bogatov <[hidden email]>
> > I managed to reproduce bug. Seems that .u file appears when svlogd is
> > restarted and there is some .s files, but not always. I plan to debug
> > it this weekend.
> >
> > Thank you for report. If you have some ideas, how to reproduce bug
> > more reliable, it would be great!
>
> Offending .u file is created by rename(2) call at line 532, in
> logdir_open() function. It happens, when 'current' file exists,
> non-executable and non-empty.
>
> Well, this is quite normal state of affairs. When `svlogd' is running,
> `current' file is getting appended, when its size reaches `ld->sizemax'
> (or something like this), it gets renames to @timestamp, and new
> `current' is created.
>
> So, if I interrupt `svlogd' at any time, but just after rotation, I
> will get this leftover .u file. I am not perfectly sure, but seems that
> `struct logdir` has `size' field, that means current size of log file.
>
> I believe following patch would solve current issue. But wouldn't
> it cause another problems? There must be reason, why this logic was
> implemented. Gerrit, some input, please?
>
> diff --git a/runit-2.1.2/src/svlogd.c b/runit-2.1.2/src/svlogd.c
> index fab8441..3f8ead4 100644
> --- a/runit-2.1.2/src/svlogd.c
> +++ b/runit-2.1.2/src/svlogd.c
> @@ -521,20 +521,7 @@ unsigned int logdir_open(struct logdir *ld, const char *fn) {
>  
>    /* open current */
>    if ((i =stat("current", &st)) != -1) {
> -    if (st.st_size && ! (st.st_mode & S_IXUSR)) {
> -      ld->fnsave[25] ='.'; ld->fnsave[26] ='u'; ld->fnsave[27] =0;
> -      do {
> -        taia_now(&now);
> -        fmt_taia(ld->fnsave, &now);
> -        errno =0;
> -      } while ((stat(ld->fnsave, &st) != -1) || (errno != error_noent));
> -      while (rename("current", ld->fnsave) == -1)
> -        pause2("unable to rename current", ld->name);
> -      rmoldest(ld);
> -      i =-1;
> -    }
> -    else
> -      ld->size =st.st_size;
> +    ld->size =st.st_size;
>    }
>    else
>      if (errno != error_noent) {

Reply | Threaded
Open this post in threaded view
|

Bug#916230: Svlogd: log files named as `timestamp.u' even if there is no processor in place

Dmitry Bogatov-3

Hello, supervision list!

I am Debian maintainer of 'runit' package, and I ask for help with
issue, described at 'https://bugs.debian.org/916230'.

There is piece of code in svlogd.c, that causes strage behaviour, but it
looks it was introduced on puprose. If you know, could you please
explain this purpose to me?

[2018-12-19 09:21] Gerrit Pape <[hidden email]>
> I'm sorry, can't give you any input, I'm busy with different things
> these days.  But there're people around knowing the runit programs and
> code, you can try to contact them through the mailing list
> <[hidden email]> .

Thank you for hint.

> On Mon, Dec 17, 2018 at 02:54:43PM +0000, Dmitry Bogatov wrote:
> >
> > [2018-12-12 19:39] Dmitry Bogatov <[hidden email]>
> > > I managed to reproduce bug. Seems that .u file appears when svlogd is
> > > restarted and there is some .s files, but not always. I plan to debug
> > > it this weekend.
> > >
> > > Thank you for report. If you have some ideas, how to reproduce bug
> > > more reliable, it would be great!
> >
> > Offending .u file is created by rename(2) call at line 532, in
> > logdir_open() function. It happens, when 'current' file exists,
> > non-executable and non-empty.
> >
> > Well, this is quite normal state of affairs. When `svlogd' is running,
> > `current' file is getting appended, when its size reaches `ld->sizemax'
> > (or something like this), it gets renames to @timestamp, and new
> > `current' is created.
> >
> > So, if I interrupt `svlogd' at any time, but just after rotation, I
> > will get this leftover .u file. I am not perfectly sure, but seems that
> > `struct logdir` has `size' field, that means current size of log file.
> >
> > I believe following patch would solve current issue. But wouldn't
> > it cause another problems? There must be reason, why this logic was
> > implemented. Gerrit, some input, please?
> >
> > diff --git a/runit-2.1.2/src/svlogd.c b/runit-2.1.2/src/svlogd.c
> > index fab8441..3f8ead4 100644
> > --- a/runit-2.1.2/src/svlogd.c
> > +++ b/runit-2.1.2/src/svlogd.c
> > @@ -521,20 +521,7 @@ unsigned int logdir_open(struct logdir *ld, const char *fn) {
> >  
> >    /* open current */
> >    if ((i =stat("current", &st)) != -1) {
> > -    if (st.st_size && ! (st.st_mode & S_IXUSR)) {
> > -      ld->fnsave[25] ='.'; ld->fnsave[26] ='u'; ld->fnsave[27] =0;
> > -      do {
> > -        taia_now(&now);
> > -        fmt_taia(ld->fnsave, &now);
> > -        errno =0;
> > -      } while ((stat(ld->fnsave, &st) != -1) || (errno != error_noent));
> > -      while (rename("current", ld->fnsave) == -1)
> > -        pause2("unable to rename current", ld->name);
> > -      rmoldest(ld);
> > -      i =-1;
> > -    }
> > -    else
> > -      ld->size =st.st_size;
> > +    ld->size =st.st_size;
> >    }
> >    else
> >      if (errno != error_noent) {
>
Reply | Threaded
Open this post in threaded view
|

Bug#916230: Log rotation issue with runit

Dmitry Bogatov-3
In reply to this post by Lorenzo Puliti

Dear submitter, please read thread above with rationale for exsting
behaviour.

Existence of those .u files means that svlogd was terminated in
non-graceful way. For example, I can confirm, that killing `svlog'
process with SIGKILL results in .u file leak.  Personally, I accumulated
number of .u files while I was debugging my runscripts.

Can you reproduce this issue with regular usage of runit -- I mean no
processs kill(2)ing, only boot, halt, reboot, /etc/service symlinks and
sv(8) tool.

If not, it is still unfortunate, that this behaviour is undocumented and
creates files with confusing names. Probably, this issue could be
somewhat alleviated by choosing another suffix (f, for `fail', maybe)
and documenting this behaviour.

Reply | Threaded
Open this post in threaded view
|

Bug#916230: Log rotation issue with runit

Jonathan de Boyne Pollard
In reply to this post by Lorenzo Puliti
Dmitry Bogatov:

> After some investigation I found code, that caused issue, but it seems
> that it was written with some purpose, yet I fail to understand that
> purpose.
>
What you need are manuals that tell you about this mechanism. (-:

* http://jdebp.eu./Softwares/nosh/guide/cyclog.html#COMPATIBILITY

* http://skarnet.org./software/s6/s6-log.html#Logdirs

* http://jdebp.eu./Softwares/djbwares/guide/multilog.html#ROTATION

* http://smarden.org/runit/svlogd.8.html#sect4

Reply | Threaded
Open this post in threaded view
|

Bug#916230: Log rotation issue with runit

Dmitry Bogatov-3
In reply to this post by Lorenzo Puliti

control: tags -1 +moreinfo +unreproducible

[2018-12-31 11:20] Lorenz <[hidden email]>

> Hi, sorry for the late response.
>
> > Can you reproduce this issue with regular usage of runit
>
> Unfortunately I am not able to reproduce systematically. I'm still trying to
> understand what causes the creation of those .u files  ( i don't do kill on
> runsv),
> but this is not easy and also will not be quick.
> I read the discussion on Supervision mailing list, I understand the
> rationale behind the creation of those .u files and i'm fine with it.
> I'm available to provide more details on Supervision list, if there is some
> interest to dig this issue there, otherwise i will try by myself.
> Feel free to put on hold or close this bug, i will reopen if I can
> find a exact sequence to reproduce with regular use.

Let it hang around for a while. I usually close bugs in 6-12 month, if
there is nobody, who can reproduce them.