Subject: [alpine-devel] [PATCH 0/8] logging framework for apk-tools

From: Dubiousjim <[email-masked]>
Date: Thu, 27 Jun 2013 18:35:41 -0400

These patches make several apk operations (default to) log into /var/log/apk.
The logging can also be disabled by a command-line option.

We don't try to log every error/warning/message, but only ones that you might
conceivably want to come back and review some days or weeks later.

The choice of which messages get logged and which don't is pretty tentative.

Dubiousjim (8):
  add logging infrastructure
  log repository updates
  log installs and deletes
  log incomplete archive unpackings
  log overwrites
  log execution of install scripts
  log cache problems
  log no dirent in archive (?)

 src/apk.c          |  4 ++++
 src/apk_database.h |  2 +-
 src/apk_defines.h  |  1 +
 src/apk_print.h    | 12 ++++++++----
 src/archive.c      |  6 +++---
 src/commit.c       |  4 ++--
 src/database.c     | 27 ++++++++++++++++++++++-----
 src/package.c      |  6 +++---
 src/print.c        | 36 ++++++++++++++++++++++++++++++------
 src/update.c       |  2 +-
 10 files changed, 75 insertions(+), 25 deletions(-)

-- 
1.8.3.1

---
Unsubscribe:  [email-masked]
Help:         [email-masked]
---

---

From: Dubiousjim <[email-masked]>
Date: Thu, 27 Jun 2013 18:35:42 -0400

---
 src/apk.c          |  4 ++++
 src/apk_database.h |  2 +-
 src/apk_defines.h  |  1 +
 src/apk_print.h    | 12 ++++++++----
 src/database.c     | 17 +++++++++++++++++
 src/print.c        | 36 ++++++++++++++++++++++++++++++------
 6 files changed, 61 insertions(+), 11 deletions(-)

diff --git a/src/apk.c b/src/apk.c
index c3709e7..4bac0ba 100644
--- a/src/apk.c
+++ b/src/apk.c
@@ -46,6 +46,7 @@ static struct apk_option generic_options[] = {
 				required_argument, "DIR" },
 	{ 'X', "repository",	"Use packages from REPO",
 				required_argument, "REPO" },
+	{ 0x113, "no-log",      "Don't write to log" },
 	{ 0x101, "progress",	"Show a progress bar" },
 	{ 0x10f, "progress-fd",	"Write progress to fd", required_argument, "FD" },
 	{ 0x110, "no-progress",	"Disable progress bar even for TTYs" },
@@ -401,6 +402,9 @@ int main(int argc, char **argv)
 		case 0x112:
 			dbopts.arch = optarg;
 			break;
+		case 0x113:
+			apk_flags |= APK_NO_LOG;
+			break;
 #ifdef TEST_MODE
 		case 0x200:
 			*apk_string_array_add(&test_repos) = (char*) optarg;
diff --git a/src/apk_database.h b/src/apk_database.h
index 3d557bd..dd975f9 100644
--- a/src/apk_database.h
+++ b/src/apk_database.h
@@ -130,7 +130,7 @@ struct apk_repository_tag {
 
 struct apk_database {
 	char *root;
-	int root_fd, lock_fd, cache_fd, keys_fd;
+	int root_fd, lock_fd, cache_fd, keys_fd, log_fd;
 	unsigned num_repos, num_repo_tags;
 	const char *cache_dir;
 	char *cache_remount_dir;
diff --git a/src/apk_defines.h b/src/apk_defines.h
index 00a6f9e..71f9fdf 100644
--- a/src/apk_defines.h
+++ b/src/apk_defines.h
@@ -65,6 +65,7 @@ extern char **apk_argv;
 #define APK_INTERACTIVE		0x0400
 #define APK_NO_NETWORK		0x1000
 #define APK_OVERLAY_FROM_STDIN	0x2000
+#define APK_NO_LOG              0x8000
 
 /* default architecture for APK packages. */
 #if defined(__x86_64__)
diff --git a/src/apk_print.h b/src/apk_print.h
index 590b8f3..4a45b73 100644
--- a/src/apk_print.h
+++ b/src/apk_print.h
@@ -14,13 +14,17 @@
 
 #include "apk_blob.h"
 
-#define apk_error(args...)	do { apk_log("ERROR: ", args); } while (0)
-#define apk_warning(args...)	do { if (apk_verbosity > 0) { apk_log("WARNING: ", args); } } while (0)
-#define apk_message(args...)	do { if (apk_verbosity > 0) { apk_log(NULL, args); } } while (0)
+#define apk_error(args...)	do { apk_log(1, 0, "ERROR: ", args); } while (0)
+#define apk_lerror(args...)	do { apk_log(1, apk_log_fd, "ERROR: ", args); } while (0)
+#define apk_warning(args...)	do { apk_log(apk_verbosity, 0, "WARNING: ", args); } while (0)
+#define apk_lwarning(args...)	do { apk_log(apk_verbosity, apk_log_fd, "WARNING: ", args); } while (0)
+#define apk_message(args...)	do { apk_log(apk_verbosity, 0, NULL, args); } while (0)
+#define apk_lmessage(args...)	do { apk_log(apk_verbosity, apk_log_fd, NULL, args); } while (0)
 
 extern int apk_progress_fd;
+extern int apk_log_fd;
 
-void apk_log(const char *prefix, const char *format, ...);
+void apk_log(int verbosity, int log_fd, const char *prefix, const char *format, ...);
 const char *apk_error_str(int error);
 
 void apk_reset_screen_width(void);
diff --git a/src/database.c b/src/database.c
index 33f7af8..5f1ca25 100644
--- a/src/database.c
+++ b/src/database.c
@@ -45,6 +45,7 @@ enum {
 
 int apk_verbosity = 1;
 unsigned int apk_flags = 0;
+int apk_log_fd = 0;
 
 static apk_blob_t tmpprefix = { .len=8, .ptr = ".apknew." };
 
@@ -54,6 +55,7 @@ static const char * const apk_static_cache_dir = "var/cache/apk";
 static const char * const apk_linked_cache_dir = "etc/apk/cache";
 
 static const char * const apk_lock_file = "var/lock/apkdb";
+static const char * const apk_log_file = "var/log/apk";
 
 static const char * const apk_world_file = "etc/apk/world";
 static const char * const apk_world_file_tmp = "etc/apk/world.new";
@@ -1326,6 +1328,7 @@ static int apk_db_create(struct apk_database *db)
 	mkdirat(db->root_fd, "var/cache/apk", 0755);
 	mkdirat(db->root_fd, "var/cache/misc", 0755);
 	mkdirat(db->root_fd, "var/lock", 0755);
+	mkdirat(db->root_fd, "var/log", 0755);
 
 	fd = openat(db->root_fd, apk_world_file, O_CREAT|O_RDWR|O_TRUNC|O_CLOEXEC, 0644);
 	if (fd < 0)
@@ -1402,6 +1405,7 @@ static void relocate_database(struct apk_database *db)
 	mkdirat(db->root_fd, "var/cache/apk", 0755);
 	mkdirat(db->root_fd, "var/cache/misc", 0755);
 	mkdirat(db->root_fd, "var/lock", 0755);
+	mkdirat(db->root_fd, "var/log", 0755);
 	apk_move_file(db->root_fd, apk_world_file_old, apk_world_file);
 	apk_move_file(db->root_fd, apk_scripts_file_old, apk_scripts_file);
 	apk_move_file(db->root_fd, apk_triggers_file_old, apk_triggers_file);
@@ -1555,6 +1559,15 @@ int apk_db_open(struct apk_database *db, struct apk_db_options *dbopts)
 			} else
 				goto ret_errno;
 		}
+		if (!(apk_flags & APK_NO_LOG)) {
+			db->log_fd = openat(db->root_fd, apk_log_file,
+					    O_CREAT | O_WRONLY | O_CLOEXEC | O_APPEND, 0644);
+			if (db->log_fd < 0) {
+				msg = "Unable to create log";
+				goto ret_errno;
+			}
+			apk_log_fd = db->log_fd;
+		}
 		if (write_arch)
 			apk_blob_to_file(db->root_fd, apk_arch_file, *db->arch, APK_BTF_ADD_EOL);
 	}
@@ -1772,6 +1785,10 @@ void apk_db_close(struct apk_database *db)
 		close(db->cache_fd);
 	if (db->root_fd)
 		close(db->root_fd);
+	if (db->log_fd) {
+		close(db->log_fd);
+		apk_log_fd = 0;
+	}
 	if (db->lock_fd)
 		close(db->lock_fd);
 	if (db->root != NULL)
diff --git a/src/print.c b/src/print.c
index 6d00064..8ab2b50 100644
--- a/src/print.c
+++ b/src/print.c
@@ -139,16 +139,40 @@ const char *apk_error_str(int error)
 	}
 }
 
-void apk_log(const char *prefix, const char *format, ...)
+void apk_log(int verbosity, int log_fd, const char *prefix, const char *format, ...)
 {
 	va_list va;
-
-	if (prefix != NULL)
-		fprintf(stderr, "%s", prefix);
+	char timestamp[20];
+	time_t t;
+	struct tm *tmp = NULL;
+
+	if (log_fd) {
+		t = time(NULL);
+		tmp = localtime(&t);
+		if (tmp != NULL) {
+			if (strftime(timestamp, sizeof(timestamp), "%b %d %T", tmp) == 0) {
+				fprintf(stderr, "ERROR: Unable to create timestamp, logging failed\n");
+				tmp = NULL;
+			} else
+				dprintf(log_fd, "%s ", timestamp);
+		}
+	}
+	if (prefix != NULL) {
+		if (tmp != NULL)
+			dprintf(log_fd, "%s", prefix);
+		if (verbosity > 0)
+			fprintf(stderr, "%s", prefix);
+	}
 	va_start(va, format);
-	vfprintf(stderr, format, va);
+	if (tmp != NULL)
+		vdprintf(log_fd, format, va);
+	if (verbosity > 0)
+		vfprintf(stderr, format, va);
 	va_end(va);
-	fprintf(stderr, "\n");
+	if (tmp != NULL)
+		dprintf(log_fd, "\n");
+	if (verbosity > 0)
+		fprintf(stderr, "\n");
 	apk_progress_force = 1;
 }
 
-- 
1.8.3.1

---

---

From: Timo Teras <[email-masked]>
Date: Fri, 28 Jun 2013 13:35:31 +0300

On Thu, 27 Jun 2013 18:35:42 -0400

>  6 files changed, 61 insertions(+), 11 deletions(-)

I do like the feature here, but not the implementation as-is.

>  	{ 0x10f, "progress-fd",	"Write progress to fd",

This might have non-wanted implications on the tmpfs initramfs
bootstrap.

I've been thinking that we need some flag for apk to indicate that it's
the tmpfs initial initramfs call to get proper defaults for flags like
these.

Also wondering if we need to support flags specially in the options
handling and always have both "foo" and "no-foo" long options.

> required_argument, "FD" }, { 0x110, "no-progress",	"Disable
> progress bar even for TTYs" }, @@ -401,6 +402,9 @@ int main(int argc,
> char **argv) case 0x112:
>  			dbopts.arch = optarg;
>  			break;
> +		case 0x113:
>  			*apk_string_array_add(&test_repos) = (char*)
> optarg; diff --git a/src/apk_database.h b/src/apk_database.h
> -#define apk_error(args...)	do { apk_log("ERROR: ", args); }
> while (0) -#define apk_warning(args...)	do { if (apk_verbosity
> > 0) { apk_log("WARNING: ", args); } } while (0) -#define
> > apk_message(args...)	do { if (apk_verbosity > 0)
> > { apk_log(NULL, args); } } while (0)
> +#define apk_error(args...)	do { apk_log(1, 0, "ERROR: ",
> args); } while (0) +#define apk_lerror(args...)	do
> { apk_log(1, apk_log_fd, "ERROR: ", args); } while (0) +#define
> apk_warning(args...)	do { apk_log(apk_verbosity, 0, "WARNING:
> ", args); } while (0) +#define apk_lwarning(args...)	do
> { apk_log(apk_verbosity, apk_log_fd, "WARNING: ", args); } while (0)
> +#define apk_message(args...)	do { apk_log(apk_verbosity, 0,
> NULL, args); } while (0) +#define apk_lmessage(args...)	do
> { apk_log(apk_verbosity, apk_log_fd, NULL, args); } while (0) extern
> int apk_progress_fd; +extern int apk_log_fd; 
> +void apk_log(int verbosity, int log_fd, const char *prefix, const
> char *format, ...); const char *apk_error_str(int error);

The inline apk_verbosity compare is there intentionally, and while in
the current code base it's not critical due to performance, I'd still
like to keep it there.

I'd likely want variants that get apk_database as parameter; or perhaps
separate apk_log_options that contains the verbosity and the logging fd
amongst other things. Might be an idea to add later logging to syslog
too.

I would also like to separate debugging message to go to separate fd.
solver.c with debug messages compiled on will fail the test cases - I'd
like those to be redirectable to separate file.

Will currently the code works with single apk_database, it is later on
perfectly reasonable to have two apk_databases open. Due to that I'd
like to keep apk_log et al not using more globals then the current ones.

> @@ -54,6 +55,7 @@ static const char * const apk_static_cache_dir =
> "var/cache/apk"; static const char * const apk_linked_cache_dir =
> "etc/apk/cache"; 
> @@ -1326,6 +1328,7 @@ static int apk_db_create(struct apk_database
> *db) mkdirat(db->root_fd, "var/cache/apk", 0755);
>  	fd = openat(db->root_fd, apk_world_file,
> O_CREAT|O_RDWR|O_TRUNC|O_CLOEXEC, 0644); if (fd < 0)
> @@ -1402,6 +1405,7 @@ static void relocate_database(struct
> apk_database *db) mkdirat(db->root_fd, "var/cache/apk", 0755);
>  	apk_move_file(db->root_fd, apk_world_file_old,
> apk_world_file); apk_move_file(db->root_fd, apk_scripts_file_old,
> apk_scripts_file); apk_move_file(db->root_fd, apk_triggers_file_old,
> apk_triggers_file); @@ -1555,6 +1559,15 @@ int apk_db_open(struct
> apk_database *db, struct apk_db_options *dbopts) } else
>  				goto ret_errno;
>  		}
>  			apk_blob_to_file(db->root_fd, apk_arch_file,
> *db->arch, APK_BTF_ADD_EOL); }
> +void apk_log(int verbosity, int log_fd, const char *prefix, const
> char *format, ...) {
>  	va_list va;
> -
> -	if (prefix != NULL)

I wonder if it is worth snprintf:ing once to a buffer with the
timestamp, and then writing to the targets where the message goes.

- Timo

---

---

From: Natanael Copa <[email-masked]>
Date: Fri, 28 Jun 2013 16:03:54 +0200

On Fri, 28 Jun 2013 13:35:31 +0300

> I do like the feature here, but not the implementation as-is.

Nice indeed. I have also thought about a log-to-logfile feature so you
have a history of what and when things were installed.

> the tmpfs initial initramfs call to get proper defaults for flags like

I am generally against apk trying to be smart but one option is to
check if --root is specified and if destination directory is a tmpfs.

maybe add a --bootstrap option which would correspond to:
 --overlay-from-stdin
 --no-network
 --clean-protected
 --initdb

I suppose the challenge here is that many of the options are
conditional. For example, if there are no apkovl, there should be no
--overlay-from-stdin (an be worked around with /dev/null tricks) and if
there are PXE network repos we replace the --no-network with
--update-cache.

The --clean-protected is currently also optional with the boot option "keep_apk_new"

> handling and always have both "foo" and "no-foo" long options.

-nc

---

---

From: Dubiousjim <[email-masked]>
Date: Thu, 27 Jun 2013 18:35:43 -0400

---
 src/update.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/update.c b/src/update.c
index ed721be..e1c7f3d 100644
--- a/src/update.c
+++ b/src/update.c
@@ -30,7 +30,7 @@ static int update_main(void *ctx, struct apk_database *db, struct apk_string_arr
 		if (APK_BLOB_IS_NULL(repo->description))
 			continue;
 
-		apk_message(BLOB_FMT " [%s]",
+		apk_lmessage(BLOB_FMT " [%s]",
 			    BLOB_PRINTF(repo->description),
 			    db->repos[i].url);
 	}
-- 
1.8.3.1

---

---

From: Dubiousjim <[email-masked]>
Date: Thu, 27 Jun 2013 18:35:44 -0400

---
 src/commit.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/src/commit.c b/src/commit.c
index 2b1eb9f..7bb0960 100644
--- a/src/commit.c
+++ b/src/commit.c
@@ -73,13 +73,13 @@ static int print_change(struct apk_database *db, struct apk_change *change,
 		return FALSE;
 
 	if (oneversion) {
-		apk_message("%s %s %s" BLOB_FMT " (" BLOB_FMT ")",
+		apk_lmessage("%s %s %s" BLOB_FMT " (" BLOB_FMT ")",
 			    status, msg,
 			    name->name,
 			    BLOB_PRINTF(db->repo_tags[change->new_repository_tag].tag),
 			    BLOB_PRINTF(*oneversion));
 	} else {
-		apk_message("%s %s %s" BLOB_FMT " (" BLOB_FMT " -> " BLOB_FMT ")",
+		apk_lmessage("%s %s %s" BLOB_FMT " (" BLOB_FMT " -> " BLOB_FMT ")",
 			    status, msg,
 			    name->name,
 			    BLOB_PRINTF(db->repo_tags[change->new_repository_tag].tag),
-- 
1.8.3.1

---

---

From: Dubiousjim <[email-masked]>
Date: Thu, 27 Jun 2013 18:35:47 -0400

---
 src/package.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/src/package.c b/src/package.c
index e211b63..b1334dc 100644
--- a/src/package.c
+++ b/src/package.c
@@ -995,7 +995,7 @@ void apk_ipkg_run_script(struct apk_installed_package *ipkg,
 		PKG_VER_PRINTF(pkg),
 		apk_script_types[type]);
 
-	apk_message("Executing %s", &fn[15]);
+	apk_lmessage("Executing %s", &fn[15]);
 	if (apk_flags & APK_SIMULATE)
 		return;
 
@@ -1025,12 +1025,12 @@ void apk_ipkg_run_script(struct apk_installed_package *ipkg,
 	apk_id_cache_reset(&db->id_cache);
 
 	if (!WIFEXITED(status) || WEXITSTATUS(status) != 0) {
-		apk_error("%s: script exited with error %d", &fn[15], WEXITSTATUS(status));
+		apk_lerror("%s: script exited with error %d", &fn[15], WEXITSTATUS(status));
 		ipkg->broken_script = 1;
 	}
 	return;
 error:
-	apk_error("%s: failed to execute: %s", &fn[15], apk_error_str(errno));
+	apk_lerror("%s: failed to execute: %s", &fn[15], apk_error_str(errno));
 	ipkg->broken_script = 1;
 }
 
-- 
1.8.3.1

---

---

From: Dubiousjim <[email-masked]>
Date: Thu, 27 Jun 2013 18:35:48 -0400

---
 src/database.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/src/database.c b/src/database.c
index ffbee26..55b19a0 100644
--- a/src/database.c
+++ b/src/database.c
@@ -1588,11 +1588,11 @@ int apk_db_open(struct apk_database *db, struct apk_db_options *dbopts)
 			/* remount cache read/write */
 			db->cache_remount_dir = find_mountpoint(db->root_fd, db->cache_dir);
 			if (db->cache_remount_dir == NULL) {
-				apk_warning("Unable to find cache directory mount point");
+				apk_lwarning("Unable to find cache directory mount point");
 			} else if (do_remount(db->cache_remount_dir, "rw") != 0) {
 				free(db->cache_remount_dir);
 				db->cache_remount_dir = NULL;
-				apk_error("Unable to remount cache read/write");
+				apk_lerror("Unable to remount cache read/write");
 				r = EROFS;
 				goto ret_r;
 			}
@@ -2583,7 +2583,7 @@ static int apk_db_unpack_pkg(struct apk_database *db,
 		if (cache_bs != NULL)
 			bs = cache_bs;
 		else
-			apk_warning(PKG_VER_FMT": unable to cache: %s",
+			apk_lwarning(PKG_VER_FMT": unable to cache: %s",
 				    PKG_VER_PRINTF(pkg), apk_error_str(errno));
 	}
 
-- 
1.8.3.1

---

---

From: Dubiousjim <[email-masked]>
Date: Thu, 27 Jun 2013 18:35:46 -0400

---
 src/database.c | 2 +-

diff --git a/src/database.c b/src/database.c
index 5f1ca25..ffbee26 100644
--- a/src/database.c
+++ b/src/database.c
@@ -2342,7 +2342,7 @@ static int apk_db_install_archive_entry(void *_ctx,
 					ipkg->broken_files = 1;
 					return 0;
 				}
-				apk_warning(PKG_VER_FMT": overwriting %s owned by "PKG_VER_FMT".",
+				apk_lwarning(PKG_VER_FMT": overwriting %s owned by "PKG_VER_FMT".",
 					    PKG_VER_PRINTF(pkg), ae->name, PKG_VER_PRINTF(opkg));
 			} while (0);
 		}
-- 
1.8.3.1

---

---

From: Dubiousjim <[email-masked]>
Date: Thu, 27 Jun 2013 18:35:49 -0400

---
 src/database.c | 2 +-

diff --git a/src/database.c b/src/database.c
index 55b19a0..a46a638 100644
--- a/src/database.c
+++ b/src/database.c
@@ -2292,7 +2292,7 @@ static int apk_db_install_archive_entry(void *_ctx,
 		diri = find_diri(ipkg, bdir, diri, &ctx->file_diri_node);
 		if (diri == NULL) {
 			if (!APK_BLOB_IS_NULL(bdir)) {
-				apk_error(PKG_VER_FMT": "BLOB_FMT": no dirent in archive\n",
+				apk_lerror(PKG_VER_FMT": "BLOB_FMT": no dirent in archive\n",
 					  pkg, BLOB_PRINTF(name));
 				ipkg->broken_files = 1;
 				return 0;
-- 
1.8.3.1

---

---

From: Dubiousjim <[email-masked]>
Date: Thu, 27 Jun 2013 18:35:45 -0400

---
 src/archive.c | 6 +++---

diff --git a/src/archive.c b/src/archive.c
index 771e548..efc8746 100644
--- a/src/archive.c
+++ b/src/archive.c
@@ -390,7 +390,7 @@ int apk_archive_entry_extract(int atfd, const struct apk_file_info *ae,
 	if (r == 0) {
 		r = fchownat(atfd, fn, ae->uid, ae->gid, atflags);
 		if (r < 0) {
-			apk_error("Failed to set ownership on %s: %s",
+			apk_lerror("Failed to set ownership on %s: %s",
 				  fn, strerror(errno));
 			return -errno;
 		}
@@ -399,7 +399,7 @@ int apk_archive_entry_extract(int atfd, const struct apk_file_info *ae,
 		if (ae->mode & 07000) {
 			r = fchmodat(atfd, fn, ae->mode & 07777, atflags);
 			if (r < 0) {
-				apk_error("Failed to set file permissions "
+				apk_lerror("Failed to set file permissions "
 					  "on %s: %s",
 					  fn, strerror(errno));
 				return -errno;
@@ -414,7 +414,7 @@ int apk_archive_entry_extract(int atfd, const struct apk_file_info *ae,
 			times[0].tv_nsec = times[1].tv_nsec = 0;
 			r = utimensat(atfd, fn, times, atflags);
 			if (r < 0) {
-				apk_error("Failed to preserve modification time on %s: %s",
+				apk_lerror("Failed to preserve modification time on %s: %s",
 					fn, strerror(errno));
 				return -errno;
 			}
-- 
1.8.3.1

---