From mboxrd@z Thu Jan  1 00:00:00 1970
Path: news.gmane.io!.POSTED.blaine.gmane.org!not-for-mail
From: Maxim Cournoyer <maxim.cournoyer@gmail.com>
Newsgroups: gmane.lisp.guile.devel
Subject: [guile-lib] (logging logger) doesn't call flush-log after each log
Date: Tue, 02 Jan 2024 21:54:22 -0500
Message-ID: <87o7e36s9t.fsf@gmail.com>
Mime-Version: 1.0
Content-Type: text/plain
Injection-Info: ciao.gmane.io; posting-host="blaine.gmane.org:116.202.254.214";
	logging-data="36995"; mail-complaints-to="usenet@ciao.gmane.io"
Cc: David Pirotte <david@altosw.be>
To: guile-devel <guile-devel@gnu.org>
Original-X-From: guile-devel-bounces+guile-devel=m.gmane-mx.org@gnu.org Wed Jan 03 03:55:02 2024
Return-path: <guile-devel-bounces+guile-devel=m.gmane-mx.org@gnu.org>
Envelope-to: guile-devel@m.gmane-mx.org
Original-Received: from lists.gnu.org ([209.51.188.17])
	by ciao.gmane.io with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256)
	(Exim 4.92)
	(envelope-from <guile-devel-bounces+guile-devel=m.gmane-mx.org@gnu.org>)
	id 1rKrPK-0009IQ-5Q
	for guile-devel@m.gmane-mx.org; Wed, 03 Jan 2024 03:55:02 +0100
Original-Received: from localhost ([::1] helo=lists1p.gnu.org)
	by lists.gnu.org with esmtp (Exim 4.90_1)
	(envelope-from <guile-devel-bounces@gnu.org>)
	id 1rKrOn-0000LY-Gu; Tue, 02 Jan 2024 21:54:29 -0500
Original-Received: from eggs.gnu.org ([2001:470:142:3::10])
 by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256)
 (Exim 4.90_1) (envelope-from <maxim.cournoyer@gmail.com>)
 id 1rKrOm-0000L4-6Z
 for guile-devel@gnu.org; Tue, 02 Jan 2024 21:54:28 -0500
Original-Received: from mail-oi1-x235.google.com ([2607:f8b0:4864:20::235])
 by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128)
 (Exim 4.90_1) (envelope-from <maxim.cournoyer@gmail.com>)
 id 1rKrOk-00022c-IO
 for guile-devel@gnu.org; Tue, 02 Jan 2024 21:54:27 -0500
Original-Received: by mail-oi1-x235.google.com with SMTP id
 5614622812f47-3bbbd4d2b4aso5059514b6e.0
 for <guile-devel@gnu.org>; Tue, 02 Jan 2024 18:54:26 -0800 (PST)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
 d=gmail.com; s=20230601; t=1704250465; x=1704855265; darn=gnu.org;
 h=mime-version:message-id:date:cc:subject:to:from:from:to:cc:subject
 :date:message-id:reply-to;
 bh=VMPM26GmwU79HBN8n+UmqF4rtX5sFZswQxxBRMVPhtA=;
 b=CQpZK+OCz74eG4gw3vNMjtw8l9D87Q9AOEO5hiCKwVAoM11bT6lyvYV3c5+uZP2iXA
 vOChUBENWa6/B5EHIT3Jjx5zZIzEOA9bXN4sfeHEQj9RlV376fYqP86go2iCrHevldMr
 qlMcz6US4g2XeFaK3vX41Xy+9uTqemKFnkFVf3wmpZorcJctBAamzDjPsixpg8TMW3aS
 tBlDH/otUVP4oU/9+auMGL6+uUrx1L4P6i191i/z2LZ1LPz6ZwJdTlUV+kD7/5FL6K7d
 tuWZLucFzXBeVdS+Jn1giR3hYNbXZPaT/a0hVx/ikzbshocg9izJsFDPSG14+KjQv9f7
 Nncg==
X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
 d=1e100.net; s=20230601; t=1704250465; x=1704855265;
 h=mime-version:message-id:date:cc:subject:to:from:x-gm-message-state
 :from:to:cc:subject:date:message-id:reply-to;
 bh=VMPM26GmwU79HBN8n+UmqF4rtX5sFZswQxxBRMVPhtA=;
 b=F3khrVj1XWe9WgISyOlUrQMC7foHMex/9UYJzAhmDriWBspIUnLEp3MW08g4E7fuVW
 qkzU3S5T2tsjXAdO/bWMFwWo0CwPTobHe7au539FUS1JkpwKPTkAFnM6u25+a/515uG+
 60Fy2ln0XHlBvZuAepLpb4Gil129zOL537fwg6Hv9H7Yww3mvhp7i6RevnI5U8MnMV1O
 Nf52A8lZhhzEJ7CK5wdDMfwN2z4XIJiefSdksp0HzqlwLIMqkP/d/12+190B2nUMr/U8
 Hzpb1Mh58WQcxosnos6kkxTlVGhMFxHKJ2hbzDfZApKy0s+i/wuiQ91e4udR/L8JRVI3
 +GUQ==
X-Gm-Message-State: AOJu0YwMzZVWYiFIrY7vXgUJAnyEHRBrcD9fITDxnSL3ucgx9Oa+YIrz
 nHkCyDMO6zVSLaL6S52n8aBB3nJhLRM=
X-Google-Smtp-Source: AGHT+IFol7He1pzwYuheuOqiAGudyqAW8AhCFYcjLIYpdJaAJJSIZWMM0f1H1jDpzggwI98cDzE+qg==
X-Received: by 2002:a05:6808:1818:b0:3bc:2720:1ca6 with SMTP id
 bh24-20020a056808181800b003bc27201ca6mr130873oib.97.1704250465111; 
 Tue, 02 Jan 2024 18:54:25 -0800 (PST)
Original-Received: from hurd (dsl-10-132-1.b2b2c.ca. [72.10.132.1])
 by smtp.gmail.com with ESMTPSA id
 y7-20020a0ce807000000b00680c444ae8asm895164qvn.61.2024.01.02.18.54.23
 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256);
 Tue, 02 Jan 2024 18:54:24 -0800 (PST)
Received-SPF: pass client-ip=2607:f8b0:4864:20::235;
 envelope-from=maxim.cournoyer@gmail.com; helo=mail-oi1-x235.google.com
X-Spam_score_int: 2
X-Spam_score: 0.2
X-Spam_bar: /
X-Spam_report: (0.2 / 5.0 requ) BAYES_00=-1.9, DKIM_SIGNED=0.1, DKIM_VALID=-0.1,
 DKIM_VALID_AU=-0.1, DKIM_VALID_EF=-0.1, FREEMAIL_FROM=0.001,
 MALFORMED_FREEMAIL=2.297, RCVD_IN_DNSWL_NONE=-0.0001, SPF_HELO_NONE=0.001,
 SPF_PASS=-0.001, T_PDS_OTHER_BAD_TLD=0.01,
 T_SCC_BODY_TEXT_LINE=-0.01 autolearn=no autolearn_force=no
X-Spam_action: no action
X-BeenThere: guile-devel@gnu.org
X-Mailman-Version: 2.1.29
Precedence: list
List-Id: "Developers list for Guile,
 the GNU extensibility library" <guile-devel.gnu.org>
List-Unsubscribe: <https://lists.gnu.org/mailman/options/guile-devel>,
 <mailto:guile-devel-request@gnu.org?subject=unsubscribe>
List-Archive: <https://lists.gnu.org/archive/html/guile-devel>
List-Post: <mailto:guile-devel@gnu.org>
List-Help: <mailto:guile-devel-request@gnu.org?subject=help>
List-Subscribe: <https://lists.gnu.org/mailman/listinfo/guile-devel>,
 <mailto:guile-devel-request@gnu.org?subject=subscribe>
Errors-To: guile-devel-bounces+guile-devel=m.gmane-mx.org@gnu.org
Original-Sender: guile-devel-bounces+guile-devel=m.gmane-mx.org@gnu.org
Xref: news.gmane.io gmane.lisp.guile.devel:22261
Archived-At: <http://permalink.gmane.org/gmane.lisp.guile.devel/22261>

Hi,

I've recently made use of guile-lib's logging library, and was surprised
that by default the rotating-log logger, which logs to a file, would
write to a file using block buffering, which would means logs would only
be seen added to the file every now and then rather than in real time.

That breaks a common expectation of log files, which can typically be
tail'd -f to see a program output as it runs.

I've come up with this workaround:

--8<---------------cut here---------------start------------->8---
    ;; Ensure log messages are written in real time, not block
    ;; buffered.
    (setvbuf (slot-ref rotating 'port) 'line)))
--8<---------------cut here---------------end--------------->8---

But it was not easily discovered and still doesn't feel exactly 'real
time'.  The Python logging library, which is the inspiration for this
one, calls 'flush' after each log message is written in the base class
from which all handlers inherit (see Lib/logging/__init__.py):

--8<---------------cut here---------------start------------->8---
class StreamHandler(Handler):
    """
    A handler class which writes logging records, appropriately formatted,
    to a stream. Note that this class does not close the stream, as
    sys.stdout or sys.stderr may be used.
    """

    terminator = '\n'

    def __init__(self, stream=None):

[...]

    def flush(self):
        """
        Flushes the stream.
        """
        self.acquire()
        try:
            if self.stream and hasattr(self.stream, "flush"):
                self.stream.flush()
        finally:
            self.release()

    def emit(self, record):
        """
        Emit a record.

        If a formatter is specified, it is used to format the record.
        The record is then written to the stream with a trailing newline.  If
        exception information is present, it is formatted using
        traceback.print_exception and appended to the stream.  If the stream
        has an 'encoding' attribute, it is used to determine how to do the
        output to the stream.
        """
        try:
            msg = self.format(record)
            stream = self.stream
            # issue 35046: merged two stream.writes into one.
            stream.write(msg + self.terminator)
            self.flush()
        except RecursionError:  # See issue 36272
            raise
        except Exception:
            self.handleError(record)

[...]
--8<---------------cut here---------------end--------------->8---

This would be easy to do in our logger implementation (we'd call
'flush-log' at the end of 'emit-log'), if we agree it's a good idea.

Would anyone be opposed to that?  If not, I'll happily send a patch.

-- 
Thanks,
Maxim