emerge.log instance id

[gyakovlev]

Would you consider changing emerge.log format a bit? currently if you ever run a emerge in another terminal in parallel it'll mangle the emerge.log and will break many parsing tools, mainly qlop. and it looks like it can't easily be fixed.

I was thinking adding a field that represents emerge instance id, so a parsing tool can determine which emerge log it's parsing. so for example a line like this

1521846850: Started emerge on: Mar 23, 2018 16:14:09

becomes

1521846850:  Started emerge on: Mar 23, 2018 16:14:09 uuid:1b92cf9a-5e2d-43a4-8fbe-3fa59b9e1c8c

and all the following lines will get their timestamp incremented as before, but id staying the same for the given instance. if a parallel instance is ever launched it will get it's own id. uuid is just an example, probably something else exists that is shorter, yet unique.

on the other hand such change will likely break existing parsers. (qlop, genlop, pqlop and maybe other tools), but if those tools get updated to handle new format they can be greatly simplified to provide accurate results without guessing.

[mgorny]

To be honest, I find emerge.log file utterly useless because its contents are written quite randomly and inconsistently. If we're going to do anything about it, I think a major overhaul would be desirable to make it really useful.

[gyakovlev]

That was my second thought. I agree it's quite inconsistent but I know nothing about it's internals.

What kind of log do you have in mind if you ever thought of that? Which phases to log? Should it log useflags or any build info? Can be useful to distinguish multilib builds from the others.

I have an example of paludis.log here it's more consistent but will suffer from the same issue of not having sane way to determine where those lines came from. paludis discourages parallel cave runs and it does not lock, so instance-id it's not that useful anyway.

1521869147: starting sync of repository x11 [0p 1a 13d]
1521869147: finished sync of repository x11 [0p 0a 14d]
1521869192: starting install of targets repository/net
1521869193: starting install of package repository/net-0::unavailable (1 of 1)
1521869206: finished install of package repository/net-0::unavailable (1 of 1)
1521869206: finished install of targets repository/net
1521870020: starting install of targets linux-headers glibc libatomic libgcc libstdc++
1521870020: starting fetch of package sys-kernel/linux-headers-4.15:0::arbor (1 of 6)
1521870020: finished fetch of package sys-kernel/linux-headers-4.15:0::arbor (1 of 6)
1521870021: starting fetch of package sys-libs/libatomic-6.4.0:6::arbor (2 of 6)
1521870021: starting fetch of package sys-kernel/linux-headers-4.15:0::arbor (1 of 6)
1521870021: finished fetch of package sys-libs/libatomic-6.4.0:6::arbor (2 of 6)
1521870021: finished fetch of package sys-kernel/linux-headers-4.15:0::arbor (1 of 6)
1521870021: starting fetch of package sys-libs/libgcc-6.4.0:6::arbor (3 of 6)
1521870021: starting install of package sys-kernel/linux-headers-4.15:0::arbor (1 of 6)
1521870021: finished fetch of package sys-libs/libgcc-6.4.0:6::arbor (3 of 6)
1521870021: starting fetch of package sys-libs/libstdc++-6.4.0:6::arbor (4 of 6)
1521870021: finished fetch of package sys-libs/libstdc++-6.4.0:6::arbor (4 of 6)
1521870021: starting fetch of package sys-libs/timezone-data-2018c:0::arbor (5 of 6)
1521870021: finished fetch of package sys-libs/timezone-data-2018c:0::arbor (5 of 6)
1521870021: starting fetch of package sys-libs/glibc-2.27:0::arbor (6 of 6)
1521870021: finished fetch of package sys-libs/glibc-2.27:0::arbor (6 of 6)

[mgorny]

My main concern was that it's hard-to-impossible to figure out whether builds (or tests) failed from emerge.log. In any case, it should certainly be complete about the fate of every package.

As for parallel, I don't use that either. The weird merging logic in Portage makes it sometimes effectively slower than serial builds.

[mgorny]

That said, for parallel instances I think listing the PID would work too (syslog-style).

[gyakovlev]

PID is not unique enough. People keep years of emerge.log and do some interesting things:

https://imgur.com/a/4d461#W0U8bFM

but if the rest of the line is unique enough it can work.

Ok I'll do my source code research, think of desired logging scope, define parse-able yet human-readable format and dump my thoughts here sometime later, it can be a good start.

should I think of something like json or keep it simple text?

[mgorny]

Let's use systemd-journald ;-).

But seriously, I think just a little refurbished text for emerge.log. We may want more machine-readable log later but that should be separate.

As for PID, as long as you define 'start' and 'exit' of the PID in emerge.log, it should be fine. It certainly is unique in context of processes running simultaneously.

[gyakovlev]

I've started dumping my initial thoughts here https://github.com/gyakovlev/emerge.lol that's to much for a little refurbished text, but I'll leave it for bright future ahead.

[mgorny]

That's a bit verbose. My emerge.log dates back to Aug 2011 and it has 47M. With your format, it'd grow very quick. I think we need to find an equilibrium between providing useful information and keeping the file in reasonable size so that tools can process it without splitting.

[mgorny]

That said, if you have free time for some homework, I think it'd be beneficial to write down how qlop and genlop parse logs (i.e. what regexp and/or logic they use), so we could establish how far we can change things without breaking compatibility.