[builddep] Report all rpm errors (RhBug:1663619,1658292)

[m-blaha]

https://bugzilla.redhat.com/show_bug.cgi?id=1663619

[dnf-bot]

[Flake8] [F841] local variable 'rpmlog' is assigned to but never used

_{posted by Sider}

[lukash]

This and the Flake8 error below should obviously be fixed in this commit and not in the subsequent one 😏

[dnf-bot]

[Flake8] [E126] continuation line over-indented for hanging indent

_{posted by Sider}

[pmatilai]

I think it'd be better to just always let rpm's messages through, or at least always capture them in a way that can be replayed in case of error. Asking user to rerun with -v just to get the error messages that always is there is a bit meh.

The rpm message sink introduced in commit 2d3dc76 was IMO always a rather strange solution to https://bugzilla.redhat.com/show_bug.cgi?id=1074461, I only provided the /dev/null sink as an example of controlling rpm's log, not as the right thing to do.

[pmatilai]

One crude but simple possibility would be opening a temporary file for the rpm log (instead of /dev/null) and dumping that out in case of parse errors.

[lukash]

@pmatilai actually, from what it says in the bz: https://bugzilla.redhat.com/show_bug.cgi?id=1663619, the user is already getting an error message from rpm: "can't parse specfile". The problem is the message is not descriptive enough. The best solution would be if rpm threw an exception that was descriptive enough.

I find the user re-running with the -v option to get additional details valid, I don't think we necessarily need to dump the (perhaps unrelated) verbose output in case of an error if the user didn't ask for it. What we really need are error messages that are descriptive enough.

Is improving the "can't parse specfile" message something you could do perhaps? 😄

[lukash]

The rearrangement of imports should go into a separate commit. e.g. imagine needing to revert this in the future and someone else adding/removing imports in between. Not only you'd revert the rearrangement unnecessarily, you'd also have an unnecessary conflict on the revert...

[lukash]

FWIW I'd change the message string to:

"Failed to open spec file '%s': %s"

The "not a valid spec file" is redundant and it's just simpler this way.

[lukash]

@m-blaha I'd welcome some description of the changes in the commit message. Along the lines of "Adding the verbose argument to the redirect_rpm_logging class and not redirecting stderr to /dev/null if it's true. Due to it being parametrized, the class cannot be a decorator anymore, change it to a context manager and use a with block." It would help people not as quick understanding the code as myself while reading the commit 😄

[pmatilai]

@lukash , https://bugzilla.redhat.com/show_bug.cgi?id=1663619 just doesn't include the rpm output of the same thing, https://bugzilla.redhat.com/show_bug.cgi?id=1547897 is more useful for understanding the issue. But in short, compare these two:

# dnf builddep /home/build/rpmbuild/SPECS/systemd.spec 
Last metadata expiration check: 9:40:09 ago on Wed 21 Feb 2018 15:32:36 UTC.
Failed to open: '/home/build/rpmbuild/SPECS/systemd.spec', not a valid spec file: can't parse specfile

[pmatilai🎩︎sopuli systemd]$ rpmspec -q systemd.spec 
error: Unable to open /home/pmatilai/rpmbuild/SOURCES/triggers.systemd: No such file or directory
error: query of specfile systemd.spec failed, can't parse

In rpm the detailed information goes to rpm log, the "can't parse" thing is just a yes/no result code.

[pmatilai]

FWIW, dnf showing uninformative/misleading errors instead of those from rpm is actually a common theme, for example https://bugzilla.redhat.com/show_bug.cgi?id=1677199 is exactly the same thing in a different setting. And unless the base approach to rpm errors is changed one way or the other, there'll be others. So instead of trying to find some minor tweak to this particular case, I'd suggest looking at the broader picture.

[lukash]

@pmatilai I'm afraid I don't understand your point... In the comparison you presented the two outputs contain basically the same information to me. I assume the detailed information can be found in the log for rpmspec and is redirected to /dev/null for 'dnf builddep`.

FWIW, dnf showing uninformative/misleading errors instead of those from rpm is actually a common theme...

Well, I'm not going to argue that's not true, I don't really know. But what I see in this case is dnf actually forwarding the rather unhelpful message rpm gives it.

I agree we should be looking at the broader picture, but at the same time if you want helpful error messages, you need to fix them one by one. It seems to be surprisingly hard to do this right. I spend significant time and effort in my reviews trying to make people write helpful and complete error messages. No way around it I guess.

For the broader picture then, is your idea to solve this to blanket-print the rpm output log in case of an error? Again, I'm rather unfamiliar with the specifics here, namely the actual content of the log output... But it does seem to me to be a somewhat lazy solution of "here, have a log dump of everything we've done and look up the error for yourself". I might be wrong. But I still prefer a single error string clearly describing the error... And then the -v for explicit verbose output. I do realize the parsing of the spec file in particular can print multiple errors, so perhaps multiline output is actually desirable and a single error string not sufficient? How about putting the first parsing error to the error string?

[pmatilai]

I'm afraid I don't understand your point... In the comparison you presented the two outputs contain basically the same information to me. I assume the detailed information can be found in the log for rpmspec and is redirected to /dev/null for 'dnf builddep`.

Um, what? Look closer. The rpmspec case shows the exact reason why it fails (a related file not found), allowing the user to understand and address the situation, dnf builddep output does not. Which is the whole point here. An error message that doesn't say why it failed is rather useless. In rpm, the why is practically always in the log, and that's so deeply rooted that there's little we can do about it.

You say you're not familiar with the contents of rpm log output, I'd suggest starting there - you can't really make a informed decisions if you don't know what you're talking about. Rpm does not log warning and error-level messages for fun, and dnf really, really should let all error-level messages from rpm to come through to the user (and preferably warnings too) one way or the other.

[lukash]

Um, what? Look closer. The rpmspec case shows the exact reason why it fails (a related file not found), allowing the user to understand and address the situation, dnf builddep output does not.

Oh, right, I was looking at the second line:

error: query of specfile systemd.spec failed, can't parse

And completely missed the first. The two lines seem unrelated to me though, unless the first is somewhat the cause for the second, which is certainly not clear from just the output.

Which is the whole point here. An error message that doesn't say why it failed is rather useless. In rpm, the why is practically always in the log, ...

Strictly speaking, the log is not the error message. The log is something to store runtime information, error messages are subset of the runtime information. For library functions throwing exceptions, the error messages are supposed to be in the exception's text.

... and that's so deeply rooted that there's little we can do about it.

Well, if that's the case... Although I'm pretty sure nothing is stopping you from improving the exception error messages.

You say you're not familiar with the contents of rpm log output, I'd suggest starting there - you can't really make a informed decisions if you don't know what you're talking about.

I've run some test commands and had a look at the log, but I'm afraid I won't get a good feel for it just by doing that, I'll need some more experience...

Rpm does not log warning and error-level messages for fun, and dnf really, really should let all error-level messages from rpm to come through to the user (and preferably warnings too) one way or the other.

But how do you actually want to do it in particular?

• You can't just pass through all the messages - it would be noisy and potentially mess with dnf's progress bars etc.
• If you only let the errors through, it will still mess with the progress bars.
• If you grab the log into a buffer and print it afterwards, it will be more or less out of context/sync with the dnf output (not sure how much this is a problem).
• Can you actually set two different log sinks with different log levels, one for the log file (with info level logging) and another to stderr for dnf? Or do you expect dnf to do some kind of filtering for errors only?
• No matter what, by doing this, dnf loses control over its output and we can no long be sure the output is concise and clean.

Do correct me if I'm wrong on anything please. I just don't see how this can work and be a good user experience / not look messy. I think a detailed proposal would be needed for this.

With all that written (...), I still think the exception error messages should be improved to contain all the information needed.

[lukash]

@m-blaha regardless of the discussion with Panu, unless there are objections to this particular PR, I think it's an improvement that makes sense and want to merge it if you address my comments...

One more question, this is specific to the builddep plugin, do we have nothing similar for other commands and do we not have similar problems there too? Thanks.

[pmatilai]

The python bindings to the rpm log are certainly spartan and don't give you much to work with, but like you noted one possibility is grabbing the log (which dnf already does...) and on errors, display any error-level messages since the last time you did that. That way you can control exactly when to output and where, and you could eg prefix the lines with rpm: or something like that to make it clear where its coming from. Out of sync is not an issue because there wont be much output there.

Further down the road, as libdnf is in C++ it has access to various things that aren't exported to python, including custom logging callbacks that you could use for better control over this stuff.

[pmatilai]

One more thing...

You can't just pass through all the messages - it would be noisy and potentially mess with dnf's progress bars etc.

There's still this strange assumption that rpm spews out tons of gibbedygoo into the log during its operation, it doesn't. This is not like running gnome/gtk applications from a terminal you know 😄

Rpm is mostly of the old-school unix style where no news is good news - rpm never logs warnings or errors without a good reason, and wiping those under the carpet is disservice to the user.

[m-blaha]

Sorry for delay. I thought about this PR again, and I think Panu is right that hiding rpm's errors and asking user to add -v is a bit cumbersome. On top of that in verbose mode the output of rpm is not even going to dnf.rpm.log. I'm marking this as "work in progress".

[lukash]

LGTM.

Just wondering, this looks like quite a complex solution to a situation which we should be having in a lot of places, but it's just applied here in a single plugin... Is this just one special case?

[pmatilai]

Just wondering, this looks like quite a complex solution to a situation which we should be having in a lot of places, but it's just applied here in a single plugin... Is this just one special case?

This is by no means an isolated case, it happens all over the place so maybe it should be dealt with in dnf core really.

[lukash]

I just happened to come across https://bugzilla.redhat.com/show_bug.cgi?id=1677199.

Should we use this approach in dnf and provide it as an API for plugins too, to handle all the cases in a unified way?

[m-blaha]

Thanks for pointing this bug out. It certainly is worth investigating.

[m-blaha]

I created PR solving the bz1677199. If this got merged, the same solution could be used also for builddep bug: rpm-software-management/dnf#1430

[m-blaha]

Rewritten to use for catching rpm log messages the same RPMTransaction() object as in base.do_transaction()

[m-blaha]

Are you sure you want to translate this string?

and should it not be:

_("RPM: {}").format(line)

instead of:

_("RPM: {}".format(line))

Thanks for catching this!
The translation is there merely for consistency - all error messages are translated. And may be for some languages like Japanese it could make some sense.