[PATCH] dmd: Allow storing early logs before writing to disk

[PATCH] dmd: Allow storing early logs before writing to disk

[David Michael]

* modules/dmd.scm (main): Start logging to a buffer instead of a
  file when the logfile option is set to "delayed".
* modules/dmd/comm.scm (start-logging-to-buffer): New procedure.
  (start-logging): If logs were being written to a string port,
  write its contents to the log file.
---

Hi,

When using dmd to bring up a read-only file system, it will quit when it
fails to open a log file for writing.

This is a proof-of-concept patch that adds the option to start writing
logs to a string port.  It allows having a dmdconf.scm that runs fsck,
makes the disk writable, and then starts writing past and future log
messages to disk with (start-logging "/var/log/dmd.log").

Does anyone have any thoughts on this?  Is there a better way to handle
this case?

Thanks.

David

 modules/dmd.scm      |  7 +++++--
 modules/dmd/comm.scm | 17 ++++++++++++++---
 2 files changed, 19 insertions(+), 5 deletions(-)

diff --git a/modules/dmd.scm b/modules/dmd.scm
index cf72d7a..e0f69c7 100644
--- a/modules/dmd.scm
+++ b/modules/dmd.scm
@@ -97,7 +97,8 @@
 		  (make <option>
 		    #:long "logfile" #:short #\l
 		    #:takes-arg? #t #:optional-arg? #f #:arg-name "FILE"
-		    #:description "log actions in FILE"
+		    #:description
+		    "log actions in FILE or to a buffer if FILE is \"delayed\""
 		    #:action (lambda (file)
 			       (set! logfile file)))
 		  (make <option>
@@ -137,7 +138,9 @@
     (and socket-file
 	 (verify-dir (dirname socket-file) insecure))
     ;; Enable logging as first action.
-    (start-logging logfile)
+    (if (string-ci=? logfile "delayed")
+      (start-logging-to-buffer)
+      (start-logging logfile))
 
     ;; Send output to log and clients.
     (set-current-output-port dmd-output-port)
diff --git a/modules/dmd/comm.scm b/modules/dmd/comm.scm
index fb08629..aeb45ca 100644
--- a/modules/dmd/comm.scm
+++ b/modules/dmd/comm.scm
@@ -37,6 +37,7 @@
             read-command
 
             start-logging
+            start-logging-to-buffer
             stop-logging
             %current-client-socket
             dmd-output-port))
@@ -103,10 +104,20 @@ return the socket."
 ;; Port for logging.  This must always be a valid port, never `#f'.
 (define log-output-port (%make-void-port "w"))
 (define (start-logging file)
-  (let ((directory (dirname file)))
+  (let ((directory (dirname file)) (oldport log-output-port))
     (unless (file-exists? directory)
-      (mkdir directory)))
-  (set! log-output-port (open-file file "al")))   ; line-buffered port
+      (mkdir directory))
+    (set! log-output-port (open-file file "al"))  ; line-buffered port
+    ;; Attempt to dump any buffered log data to the given log file.  This only
+    ;; succeeds if log-output-port was an open output string port, as verified
+    ;; by get-output-string.  Otherwise, logging to a file is started normally.
+    (catch #t
+      (lambda ()
+        (display (get-output-string oldport) log-output-port)
+        (close-output-port oldport))
+      noop)))
+(define (start-logging-to-buffer)
+  (set! log-output-port (open-output-string)))
 (define (stop-logging)
   (close-port log-output-port)
   (set! log-output-port (%make-void-port "w")))
-- 
1.9.3

Re: [PATCH] dmd: Allow storing early logs before writing to disk

[Ludovic Courtès]

David Michael <fedora.dm0@gmail.com> skribis:

> When using dmd to bring up a read-only file system, it will quit when it
> fails to open a log file for writing.

Out of curiosity, are you trying to use dmd in the initrd, or maybe on
GNU/Hurd?

> This is a proof-of-concept patch that adds the option to start writing
> logs to a string port.  It allows having a dmdconf.scm that runs fsck,
> makes the disk writable, and then starts writing past and future log
> messages to disk with (start-logging "/var/log/dmd.log").

That sounds useful.

> Does anyone have any thoughts on this?  Is there a better way to handle
> this case?

The problem is: when does it figure out that it can now write to the
file?

The ideal thing would be:

  1. Run ‘dmd -l foo.log’.
  2. If foo.log is not writable, then make ‘log-output-port’ a string
     port.
  3. When foo.log becomes writable, have ‘log-output-port’ point to it
     and dump previously buffered data.

But #3 is difficult.

Maybe instead of using a string port, we could use a string port that
keeps trying to open the log file?

It would be best to use inotify (or the Hurd’s fs_notify), of course.

Ludo’.

Re: [PATCH] dmd: Allow storing early logs before writing to disk

[David Michael]

On Thu, Sep 11, 2014 at 10:31 AM, Ludovic Courtès <ludo@gnu.org> wrote:
> David Michael <fedora.dm0@gmail.com> skribis:
>
>> When using dmd to bring up a read-only file system, it will quit when it
>> fails to open a log file for writing.
>
> Out of curiosity, are you trying to use dmd in the initrd, or maybe on
> GNU/Hurd?

I've replaced Hurd's /libexec/runsystem script with dmd; i.e., Hurd's
own init program is launching dmd.  There are some pending patches to
restructure the Hurd system startup, so I'll probably try to use dmd
as the real init process once those are accepted.

>> This is a proof-of-concept patch that adds the option to start writing
>> logs to a string port.  It allows having a dmdconf.scm that runs fsck,
>> makes the disk writable, and then starts writing past and future log
>> messages to disk with (start-logging "/var/log/dmd.log").
>
> That sounds useful.
>
>> Does anyone have any thoughts on this?  Is there a better way to handle
>> this case?
>
> The problem is: when does it figure out that it can now write to the
> file?

This patch expects that dmd is explicitly told when it's safe to write
the file.  (See reasoning/concerns below.)  A dmdconf.scm could do
something like this on boot with it.

    ;; The system was booted read-only ...
    (system* "/sbin/fsck" "--preen" "--writable")
    ;; Now it's writable (on success), so dump saved log lines to disk
    (start-logging "/var/log/dmd.log")

> The ideal thing would be:
>
>   1. Run ‘dmd -l foo.log’.
>   2. If foo.log is not writable, then make ‘log-output-port’ a string
>      port.

Do you think it makes sense to define log-output-port as a string port
at first instead of a void port?

>   3. When foo.log becomes writable, have ‘log-output-port’ point to it
>      and dump previously buffered data.
>
> But #3 is difficult.
>
> Maybe instead of using a string port, we could use a string port that
> keeps trying to open the log file?
>
> It would be best to use inotify (or the Hurd’s fs_notify), of course.

Something like that would be a nice transparent solution for read-only
booting, but I could see another issue arising from it later.  It's
common to have /var or /var/log on a different volume that may not be
mounted when the root file system's /var/log is writable.  Writing
logs as soon as possible could miss the sysadmin's desired log volume
(which theoretically could also happen with dmd as is).

I haven't done the research, but I'd imagine if other init systems
write anything to persistent storage, it would be done after fscking
and/or mounting all relevant entries in /etc/fstab.  It doesn't look
like dmd is currently doing any /etc/fstab processing, so I've
included some of that in my dmdconf.scm, and the explicit procedure
call to start logging declares that the file systems are now in a
usable state.  Admittedly, it might not be necessary to worry about
mounting volumes when you have passive translators, but it may be
cause for concern if the same functionality is used with Linux.

So, maybe this patch was just a band-aid on a lack of early
mount-handling.  I'll go and ponder this some more.

Thanks.

David

Re: [PATCH] dmd: Allow storing early logs before writing to disk

[Ludovic Courtès]

David Michael <fedora.dm0@gmail.com> skribis:

> On Thu, Sep 11, 2014 at 10:31 AM, Ludovic Courtès <ludo@gnu.org> wrote:
>> David Michael <fedora.dm0@gmail.com> skribis:
>>
>>> When using dmd to bring up a read-only file system, it will quit when it
>>> fails to open a log file for writing.
>>
>> Out of curiosity, are you trying to use dmd in the initrd, or maybe on
>> GNU/Hurd?
>
> I've replaced Hurd's /libexec/runsystem script with dmd; i.e., Hurd's
> own init program is launching dmd.  There are some pending patches to
> restructure the Hurd system startup, so I'll probably try to use dmd
> as the real init process once those are accepted.

Nice!

>>> This is a proof-of-concept patch that adds the option to start writing
>>> logs to a string port.  It allows having a dmdconf.scm that runs fsck,
>>> makes the disk writable, and then starts writing past and future log
>>> messages to disk with (start-logging "/var/log/dmd.log").
>>
>> That sounds useful.
>>
>>> Does anyone have any thoughts on this?  Is there a better way to handle
>>> this case?
>>
>> The problem is: when does it figure out that it can now write to the
>> file?
>
> This patch expects that dmd is explicitly told when it's safe to write
> the file.  (See reasoning/concerns below.)  A dmdconf.scm could do
> something like this on boot with it.
>
>     ;; The system was booted read-only ...
>     (system* "/sbin/fsck" "--preen" "--writable")
>     ;; Now it's writable (on success), so dump saved log lines to disk
>     (start-logging "/var/log/dmd.log")

OK.

>> The ideal thing would be:
>>
>>   1. Run ‘dmd -l foo.log’.
>>   2. If foo.log is not writable, then make ‘log-output-port’ a string
>>      port.
>
> Do you think it makes sense to define log-output-port as a string port
> at first instead of a void port?

No, because running dmd without ‘-l’ means disabling logging altogether,
hence the void port.

>>   3. When foo.log becomes writable, have ‘log-output-port’ point to it
>>      and dump previously buffered data.
>>
>> But #3 is difficult.
>>
>> Maybe instead of using a string port, we could use a string port that
>> keeps trying to open the log file?
>>
>> It would be best to use inotify (or the Hurd’s fs_notify), of course.
>
> Something like that would be a nice transparent solution for read-only
> booting, but I could see another issue arising from it later.  It's
> common to have /var or /var/log on a different volume that may not be
> mounted when the root file system's /var/log is writable.  Writing
> logs as soon as possible could miss the sysadmin's desired log volume
> (which theoretically could also happen with dmd as is).

Right, that makes sense.  I think it’s a good argument against trying to
do something too smart.

So probably the patch you propose is the best approach.

Then I would suggest a small change: instead of the magic
‘--log-file=delayed’, what about adding a new option, say,
‘--buffered-log’?  WDYT?

> I haven't done the research, but I'd imagine if other init systems
> write anything to persistent storage, it would be done after fscking
> and/or mounting all relevant entries in /etc/fstab.  It doesn't look
> like dmd is currently doing any /etc/fstab processing, so I've
> included some of that in my dmdconf.scm, and the explicit procedure
> call to start logging declares that the file systems are now in a
> usable state.  Admittedly, it might not be necessary to worry about
> mounting volumes when you have passive translators, but it may be
> cause for concern if the same functionality is used with Linux.

Yeah passive translators greatly simplify things, at the expense of
making it more difficult to track changes to the system configuration.

For the Linux-based distro we don’t use dmd in the initrd.  This is
unfortunate because that leads to some code duplication between initrd
vs. full system, but OTOH, there would be complications with having dmd
do the switch-root thing, I think.

Thanks,
Ludo’.

Re: [PATCH] dmd: Allow storing early logs before writing to disk

[David Michael]

On Sat, Sep 13, 2014 at 8:16 AM, Ludovic Courtès <ludo@gnu.org> wrote:
> David Michael <fedora.dm0@gmail.com> skribis:
>> On Thu, Sep 11, 2014 at 10:31 AM, Ludovic Courtès <ludo@gnu.org> wrote:
[snip]
>>> The ideal thing would be:
>>>
>>>   1. Run ‘dmd -l foo.log’.
>>>   2. If foo.log is not writable, then make ‘log-output-port’ a string
>>>      port.
>>
>> Do you think it makes sense to define log-output-port as a string port
>> at first instead of a void port?
>
> No, because running dmd without ‘-l’ means disabling logging altogether,
> hence the void port.

That doesn't appear to be the case.  The main procedure in
modules/dmd.scm is calling start-logging unconditionally, with the
default log file if the option is omitted.

>>>   3. When foo.log becomes writable, have ‘log-output-port’ point to it
>>>      and dump previously buffered data.
>>>
>>> But #3 is difficult.
>>>
>>> Maybe instead of using a string port, we could use a string port that
>>> keeps trying to open the log file?
>>>
>>> It would be best to use inotify (or the Hurd’s fs_notify), of course.
>>
>> Something like that would be a nice transparent solution for read-only
>> booting, but I could see another issue arising from it later.  It's
>> common to have /var or /var/log on a different volume that may not be
>> mounted when the root file system's /var/log is writable.  Writing
>> logs as soon as possible could miss the sysadmin's desired log volume
>> (which theoretically could also happen with dmd as is).
>
> Right, that makes sense.  I think it’s a good argument against trying to
> do something too smart.
>
> So probably the patch you propose is the best approach.
>
> Then I would suggest a small change: instead of the magic
> ‘--log-file=delayed’, what about adding a new option, say,
> ‘--buffered-log’?  WDYT?

Yes, I think a separate option would be better.  If it's expected that
users will handle early mount configuration in their dmdconf.scm,
separate options could allow doing something like specifying both
options and starting to write to the given log file automatically
after processing dmdconf.scm, if it wasn't started explicitly.  That
could at least remove the need for the user to have to know to start
logging themselves.

I haven't had a chance to try rewriting this yet, but I can send a new
version when I do.

Thanks.

David

Re: [PATCH] dmd: Allow storing early logs before writing to disk

[Ludovic Courtès]

David Michael <fedora.dm0@gmail.com> skribis:

> On Sat, Sep 13, 2014 at 8:16 AM, Ludovic Courtès <ludo@gnu.org> wrote:
>> David Michael <fedora.dm0@gmail.com> skribis:
>>> On Thu, Sep 11, 2014 at 10:31 AM, Ludovic Courtès <ludo@gnu.org> wrote:
> [snip]
>>>> The ideal thing would be:
>>>>
>>>>   1. Run ‘dmd -l foo.log’.
>>>>   2. If foo.log is not writable, then make ‘log-output-port’ a string
>>>>      port.
>>>
>>> Do you think it makes sense to define log-output-port as a string port
>>> at first instead of a void port?
>>
>> No, because running dmd without ‘-l’ means disabling logging altogether,
>> hence the void port.
>
> That doesn't appear to be the case.  The main procedure in
> modules/dmd.scm is calling start-logging unconditionally, with the
> default log file if the option is omitted.

Oh indeed, you’re right.

[...]

>> So probably the patch you propose is the best approach.
>>
>> Then I would suggest a small change: instead of the magic
>> ‘--log-file=delayed’, what about adding a new option, say,
>> ‘--buffered-log’?  WDYT?
>
> Yes, I think a separate option would be better.  If it's expected that
> users will handle early mount configuration in their dmdconf.scm,
> separate options could allow doing something like specifying both
> options and starting to write to the given log file automatically
> after processing dmdconf.scm, if it wasn't started explicitly.  That
> could at least remove the need for the user to have to know to start
> logging themselves.

Rather, I would expect that the service that mounts the file system
/var/log is on would explicitly call ‘start-logging’ (because it could
be that things aren’t ready yet after dmdconf.scm has been loaded.)

> I haven't had a chance to try rewriting this yet, but I can send a new
> version when I do.

Great, thanks.

Ludo’.