From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp10.migadu.com ([2001:41d0:8:6d80::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms5.migadu.com with LMTPS id kOPLLhDTemNvQAAAbAwnHQ (envelope-from ) for ; Mon, 21 Nov 2022 02:23:28 +0100 Received: from aspmx1.migadu.com ([2001:41d0:8:6d80::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp10.migadu.com with LMTPS id 4OfcLRDTemPDfAAAG6o9tA (envelope-from ) for ; Mon, 21 Nov 2022 02:23:28 +0100 Received: from lists.gnu.org (lists.gnu.org [209.51.188.17]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by aspmx1.migadu.com (Postfix) with ESMTPS id 62A1E2DF03 for ; Mon, 21 Nov 2022 02:23:27 +0100 (CET) Received: from localhost ([::1] helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1owvWb-0002Xi-6Z; Sun, 20 Nov 2022 20:23:05 -0500 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 ) id 1owvWY-0002XB-Vz for bug-guix@gnu.org; Sun, 20 Nov 2022 20:23:03 -0500 Received: from debbugs.gnu.org ([209.51.188.43]) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1owvWY-0000bq-Nx for bug-guix@gnu.org; Sun, 20 Nov 2022 20:23:02 -0500 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1owvWX-0002Ag-W4 for bug-guix@gnu.org; Sun, 20 Nov 2022 20:23:02 -0500 Subject: bug#36510: confusing mcron logging Resent-From: Maxim Cournoyer Original-Sender: "Debbugs-submit" Resent-To: bug-guix@gnu.org Resent-Date: Mon, 21 Nov 2022 01:23:01 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: cc-closed 36510 X-GNU-PR-Package: guix X-GNU-PR-Keywords: To: Dale Mellor Cc: 36510-done@debbugs.gnu.org Mail-Followup-To: 36510@debbugs.gnu.org, maxim.cournoyer@gmail.com, rob@vllmrt.net Received: via spool by 36510-done@debbugs.gnu.org id=D36510.16689937548293 (code D ref 36510); Mon, 21 Nov 2022 01:23:01 +0000 Received: (at 36510-done) by debbugs.gnu.org; 21 Nov 2022 01:22:34 +0000 Received: from localhost ([127.0.0.1]:44945 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1owvW5-00029g-Sm for submit@debbugs.gnu.org; Sun, 20 Nov 2022 20:22:34 -0500 Received: from mail-qk1-f180.google.com ([209.85.222.180]:34561) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1owvW4-00029T-Br for 36510-done@debbugs.gnu.org; Sun, 20 Nov 2022 20:22:33 -0500 Received: by mail-qk1-f180.google.com with SMTP id 8so7179990qka.1 for <36510-done@debbugs.gnu.org>; Sun, 20 Nov 2022 17:22:32 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=mime-version:user-agent:message-id:in-reply-to:date:references :subject:cc:to:from:from:to:cc:subject:date:message-id:reply-to; bh=Ox6LwgXCUKvYZ1rCRZh4SaI1+o3nDoxMlMUGH/I0EAU=; b=K9Myvb6syx3S0gXRbzDCUUJr/MExUg5wj++b8lPpd6Bu/EsXr+I+uoM+Z322Ydr3fM Wk6EZR3igOB8kc8rWLOwTQ/XCYRlaaxkhpDZIV2Kbngqb81R2lZYyChS9uNECCAqURlW 3XHvxV5sL7yUVTA4rttkEAGL4hPYGBBZ2pgNOnuMNstYwyp26tu4qIdK9C8Hkol1WsL3 w5qa/zgcpmYEOKMwwjMdD9IiI4Q8S+Y3h2byfe4Y/W2lyyOR8O+GjAaJ5veT3b9nhjx+ SbbY1fTiGH+95q1qzmsPx+cNGRLLyzYeZrdbfWoRsb3lXwH/sL6hlAlc2XBJYwbuvTyN 8bvQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=mime-version:user-agent:message-id:in-reply-to:date:references :subject:cc:to:from:x-gm-message-state:from:to:cc:subject:date :message-id:reply-to; bh=Ox6LwgXCUKvYZ1rCRZh4SaI1+o3nDoxMlMUGH/I0EAU=; b=HUS3thn49S1FpHJa1LOlETOzpUjONAWY8uA+RAmPVvh/GDv1pBH0k5ZRJFCvOQJ5k2 p6mQvmn2tK9/oHU4LOfL6xLC7cnLAwvKVQQkUjyPzwMojYIYbVuXnjwjy3YMfN/gdymf o6CiLVQ9uT9/RX97LsxIAkGGRNUc3IeGNxhTYFO7LypcQ1a8f8Aqm0KMvCKMLmqloXCP CCght+Lz8ixWdDq1Bo90ABzBgOZKRUYbl4c5f9XjQoJhvbTsK2efsdZ9WOyX5Hiu2e8H 6TWXzxpDqvR+cLrL0VnL8q1kIXOKE80xArK5aD4T3QYNgy7jqxfE+T/Rl4y0WpeBY27p gcBw== X-Gm-Message-State: ANoB5pk5i47yuei85Q1DnyEuWGe949UJipCacl7TRC6hFWcQyrHFALgq QU8WW4NtZHJkF6tJqfzI4BzaCNjBfpE= X-Google-Smtp-Source: AA0mqf5XetJQicXRTs3ixP51nBh9vVSXkawkJc2c3UhkJXHCd8AEdBFXF0EXKB44YefZhagx7Hvdng== X-Received: by 2002:ae9:ee1a:0:b0:6fa:3f2c:c654 with SMTP id i26-20020ae9ee1a000000b006fa3f2cc654mr2654410qkg.78.1668993746565; Sun, 20 Nov 2022 17:22:26 -0800 (PST) Received: from hurd (dsl-141-193.b2b2c.ca. [66.158.141.193]) by smtp.gmail.com with ESMTPSA id d7-20020ac86147000000b003a5c60686b0sm6075736qtm.22.2022.11.20.17.22.25 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sun, 20 Nov 2022 17:22:26 -0800 (PST) From: Maxim Cournoyer References: <90FD0C85-F140-420C-AD90-3C2776D8B8D0@vllmrt.net> <0b026b7cd95151875bf47958fc70b52764816d71.camel@rdmp.org> Date: Sun, 20 Nov 2022 20:22:25 -0500 In-Reply-To: <0b026b7cd95151875bf47958fc70b52764816d71.camel@rdmp.org> (Dale Mellor's message of "Tue, 04 Jan 2022 13:21:44 +0000") Message-ID: <874jut2jam.fsf_-_@gmail.com> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/28.2 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list X-BeenThere: bug-guix@gnu.org List-Id: Bug reports for GNU Guix List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: bug-guix-bounces+larch=yhetil.org@gnu.org Sender: bug-guix-bounces+larch=yhetil.org@gnu.org X-Migadu-Flow: FLOW_IN X-Migadu-Country: US ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=yhetil.org; s=key1; t=1668993808; h=from:from:sender:sender:reply-to:subject:subject:date:date: message-id:message-id:to:to:cc:cc:mime-version:mime-version: content-type:content-type:resent-to:resent-from:resent-sender: resent-message-id:in-reply-to:in-reply-to:references:references: list-id:list-help:list-unsubscribe:list-subscribe:list-post: dkim-signature; bh=Ox6LwgXCUKvYZ1rCRZh4SaI1+o3nDoxMlMUGH/I0EAU=; b=Vo/eMSh5AEulH7vzyVQeg5FjXTKe2Kaw3yEShynbpv0NfsyUcUbBxk7h4QGPV65VU6U0VU ZYzZy5j/rsRNaRdlDpOgO9aPwnVuIrdOgwmLa2ovuCHr0ePBq8/oU1kG3oQmZ8S3JIh/Wp g4VCvrM/uXG4+Y5TPQAM1LxO6UX+woTT+AUpP0FrIeIjR21Em9jxDwiwKjk0/EVV6KFFrm sy34+onIPZMf8w9u/f441eRf6sskP1JIc8jlAUC63JwF9c7p/UQqsyuT9L0d55MaI+Wd4d QKzBBMtMVqK6PShKfUTdGrZnN895C8AA3h1EUBfpA0XTFIjpS6UpbxgEo3Db8A== ARC-Seal: i=1; s=key1; d=yhetil.org; t=1668993808; a=rsa-sha256; cv=none; b=A+drHkLMGOg57Zdffri57emyKPqiBqb+TFNRs8dDXGxd1RIc32kR3KKF3I/bk9lB6vVHhX V+5uYSBEWLKg7z119OVrpprxAJBTGMXCTzC6uotUyRjDN0vwbP7DF7PO/hw5Ry0Nvufsba hw77FnJNcgRubJPdrdcBkgIVmxVjtGdLvSr5djUSNqJb9cqKmwFLYgjIsXMn6pxU5fYIjI rXs15MrBQI/QdE8jA+VbDOkNwx8ami0enTllRX92AnMCuu62Bm2US0r+TTaL3p+Wcp0NGv SfDhe7Omk46HoZfES0q75pidJ4fDjW/+FqnLvCOVHlV9o+kX56YVEsPq+51DOw== ARC-Authentication-Results: i=1; aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=gmail.com header.s=20210112 header.b=K9Myvb6s; dmarc=fail reason="SPF not aligned (relaxed)" header.from=gmail.com (policy=none); spf=pass (aspmx1.migadu.com: domain of "bug-guix-bounces+larch=yhetil.org@gnu.org" designates 209.51.188.17 as permitted sender) smtp.mailfrom="bug-guix-bounces+larch=yhetil.org@gnu.org" X-Migadu-Spam-Score: 6.00 Authentication-Results: aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=gmail.com header.s=20210112 header.b=K9Myvb6s; dmarc=fail reason="SPF not aligned (relaxed)" header.from=gmail.com (policy=none); spf=pass (aspmx1.migadu.com: domain of "bug-guix-bounces+larch=yhetil.org@gnu.org" designates 209.51.188.17 as permitted sender) smtp.mailfrom="bug-guix-bounces+larch=yhetil.org@gnu.org" X-Migadu-Queue-Id: 62A1E2DF03 X-Spam-Score: 6.00 X-Migadu-Scanner: scn1.migadu.com X-TUID: i0xMnuBOIpZT Hello Dale, Dale Mellor writes: > Hi, sorry for the delay but I've had a bit of time over Christmas > to look things over. I've given this a lot of consideration. Apologies for my lack of reply thus far, it seems your mail had fallen in cracks. > > I am happy to drop compatibility with guile-2.2 and older; I think we > can make a minor version bump for this break with legacy. > > > > Does this belong in mcron? The mcron source code is currently > 3,000 lines, to which you are bringing over 500 new ones to > make a facility which is geared towards debugging in the GUIX > system (I am all-in on GUIX myself, but mcron is a generic GNU > program with use-cases outside of this system). I wonder if > this is the best place: perhaps it is shepherd, which is > responsible for the /var/log/mcron.log file, to be responsible > for the amended logging messages? And then again, isn't this > exactly what syslogd does anyway? Most likely timings will be > more accurate if they are generated in mcron. Since Shepherd 0.9+, it now appends logging information to every output it handles, so this feature has indeed become less important, but still useful: I've recently bumped our package of mcron in Guix and I'm using its annotation facility to prepend the process ID to its output. I think the grunt of new lines added must be as documentation and test code, so that's not so bad as it seems I think. > In your use-case, of debugging the system, I would think that > more specialized messages placed directly in the cron jobs > themselves would be a better aid to your work, as you can > target them to the problem at hand. And you could send those > to syslogd if you wanted. Here's a sample output from the Guix build farm: --8<---------------cut here---------------start------------->8--- 2022-11-21 01:56:15 84005 /gnu/store/ypyz886hd7qaw0g8ba5a595dc0qgnj3q-update-guix.gnu.org: running... 2022-11-21 01:59:24 84005 /gnu/store/ypyz886hd7qaw0g8ba5a595dc0qgnj3q-update-guix.gnu.org: Updating channel 'guix' from Git repository at 'https://git.savannah.gnu.org/git/guix.git'... 2022-11-21 01:59:24 84005 /gnu/store/ypyz886hd7qaw0g8ba5a595dc0qgnj3q-update-guix.gnu.org: Computing Guix derivation for 'x86_64-linux'... 2022-11-21 01:59:24 84005 /gnu/store/ypyz886hd7qaw0g8ba5a595dc0qgnj3q-update-guix.gnu.org: [2022-11-21T01:56:18+0100] building web site from 'https://git.savannah.gnu.org/git/guix/guix-artwork.git'... 2022-11-21 01:59:24 84005 /gnu/store/ypyz886hd7qaw0g8ba5a595dc0qgnj3q-update-guix.gnu.org: completed in 189.325s 2022-11-21 02:00:00 91665 /gnu/store/xsc4x68avp8nmrf3hgvhd26yl3k90jqz-check-disk-space: running... 2022-11-21 02:00:00 91665 /gnu/store/xsc4x68avp8nmrf3hgvhd26yl3k90jqz-check-disk-space: completed in 0.046s --8<---------------cut here---------------end--------------->8--- The timestamp is now generated by Shepherd, and mcron adds the PID of the job, such as 84005 above. To have some indication of how long the job ran available at a quick glance is very useful for admin purposes. > > > The output is a little unpredictable. The script (which is > admittedly somewhat pathological) > > (job '(next-second '(0 30)) '(begin (display "test: ") > (system "date"))) > > produces > > 2022-01-04T11:24:00 (...): running... > 2022-01-04T11:24:00 (...): Tue 4 Jan 11:24:00 GMT 2022 > 2022-01-04T11:24:00 (...): test: completed in 0.022s > 2022-01-04T11:24:30 (...): running... > 2022-01-04T11:24:30 (...): Tue 4 Jan 11:24:30 GMT 2022 > 2022-01-04T11:25:00 (...): running... > 2022-01-04T11:25:00 (...): Tue 4 Jan 11:25:00 GMT 2022 > ... I've noticed that too, that some jobs somehow escape producing the "completed in x..." message. I'll try looking into that, it's probably a subtle bug. > But all things considered your changes are generally useful to > have, including outside of the GUIX system, and I would very > much like to have them there. But to be sure not to break any > existing applications, I would like the changes to be opt-in > via a command-line switch -l; the --log-format option can > remain to customize this (please also make -L a short option > alternative; also -D as short for --date-format). > > I am willing and able to do this work myself in a reasonable > time-frame if you would like me to. Thank you for taking on yourself the above work, Dale! I was happily surprise to see this change had landed with your improvement on top. I think this Guix issue can now be closed :-). -- Thanks, Maxim