ui: don't show exception for "Too many files" error

[efiop]

iterative/dvc.org#875 (comment)

Stops showing the exception in non-verbose mode, but shows full
traceback in verbose mode.

Introducing our custom parameter tb_only through standard extra
logging parameter.

• ❗ Have you followed the guidelines in the Contributing to DVC list?

• 📖 Check this box if this PR does not require documentation updates, or if it does and you have created a separate PR in dvc.org with such updates (or at least opened an issue about it in that repo). Please link below to your PR (or issue) in the dvc.org repo.

• ❌ Have you checked DeepSource, CodeClimate, and other sanity checks below? We consider their findings recommendatory and don't expect everything to be addressed. Please review them carefully and fix those that actually improve code or fix bugs.

Thank you for the contribution - we'll try to review it as soon as possible. 🙏

[shcheklein]

@efiop can include the output after this change, please?

[efiop]

@shcheklein not sure I follow, could you rephrase, please?

[shcheklein]

@shcheklein not sure I follow, could you rephrase, please?

I mean the CLI output after this changes vs what was before. The same way as @pared included then in the docs discussion. It's hard otherwise to see the difference and understand how does it looks like.

[efiop]

@shcheklein Ah, right. So before:

ERROR: too many open files, please increase your `ulimit` - [Errno 24] Too many open files: '/home/prd/development/projects/playground/2473/repo/.dvc/cache/10/788f0c3b6f08ef6
f183f49490183d0'


Having any troubles? Hit us up at https://dvc.org/support, we are always happy to help!

after:

ERROR: too many open files, please increase your `ulimit`


Having any troubles? Hit us up at https://dvc.org/support, we are always happy to help!

[shcheklein]

@efiop so, i'm lost then :) how does it correspond with this one - iterative/dvc.org#875 (comment) ? was it just a suggestion?

[efiop]

@shcheklein I've removed the unnecessary second Too many open files and the filename. I didn't touch the main message itself, as it will be handled by @pared in #3017

[shcheklein]

@efiop got it! thanks.

[ghost]

looks good 👍

[ghost]

@efiop , what about showing the whole stack every time?

[efiop]

@MrOutis what about it? We don't unless -v is specified, the same as it was before.

mhm, then I think I didn't get the purpose of this PR

[ghost]

Why are you passing the stack_info=True if you are not showing it on #3058 (comment) ?

[efiop]

@MrOutis I do, but only on -v, because it is our policy. I should've explicitly clarified, that default logger.exception/error methods have exc_info and stack_info params. For error exc_info is None by default, so it doesn't show it and stack_info is False by default for both error/exception. So my change takes advantage of those defaults so that error get's exc_info=None, but stack_info=True, which tells it to not show the exception but show its traceback.

[ghost]

@efiop , it is hard to me to review this 🤔 I have mixed feelings about the way we are handling exceptions and displaying error messages.

I think the don't show exception for "Too many files" error could be solved by doing raise ... from None to delete the cause of the exception.

[Errno 24] Too many open files: '/home/prd/development/projects/playground/2473/repo/.dvc/cache/10/788f0c3b6f08ef6f183f49490183d0' is the exception's .__cause__.

The "Too many files" is the message that we are displaying with logger.exception("").

Still confused why we need to deal with the stack trace.

---

By the way, @efiop , the WIP PR that I was talking about is right here: #3059 😅

[efiop]

I think the don't show exception for "Too many files" error could be solved by doing raise ... from None` to delete the cause of the exception.

But raise where? We don't have control over it, so we will have to hack to delete the exception.

Also, that would remove the traceback from -v output too, which is harmful, as it will deprive us of debug info.

[ghost]

Also, that would remove the traceback from -v output too, which is harmful, as it will deprive us of debug info.

True that.

Anyways, using stack_info seems like a hack, since we are not displaying it.

I'd better opt to add an extra argument to the exception itself and handle it correctly on the logger.

    except Exception as exc:  # pylint: disable=broad-except
        if isinstance(exc, OSError) and exc.errno == errno.EMFILE:
            exc.display_only_message = True

            logger.exception(
                "too many open files, please increase your `ulimit`"
            )

---

EDIT: It looks ugly 😅

There's another one, modifying the exception arguments, if we don't care about the message:

    except Exception as exc:  # pylint: disable=broad-except
        if isinstance(exc, OSError) and exc.errno == errno.EMFILE:
            exc.args = ("too many open files, please increase your `ulimit`",)
            logger.exception("")

EDIT 2: Ok ok, a mix of both approaches:

    except Exception as exc:  # pylint: disable=broad-except
        if isinstance(exc, OSError) and exc.errno == errno.EMFILE:
            exc.alternative_message = "too many open files, please increase your `ulimit`"
            logger.exception("")

and a one-liner (without tests 😅 ) change in the following PR: #3059)

@@ -65,7 +65,7 @@ class ColorFormatter(logging.Formatter):
             info = "{message}{separator}{exception}{cause}".format(
                 message=record.msg or "",
                 separator=" - " if record.msg and exception.args else "",
-                exception=exception,
+                exception=exception.alt_message or exception,
                 cause=": " + str(cause) if cause else "",
             )

[efiop]

Anyways, using stack_info seems like a hack, since we are not displaying it.

We NEVER display tracebacks in non-verbose mode, hence why we have all that code in logger.py to handle it. stack_info is a standard mechanism to tell logger to show the stacktrace and it is part of the standard to use it with exc_info in any combination. (see https://docs.python.org/3/library/logging.html#logging.Logger.debug) Our current formatter doesn't process stack_info argument at all(it does use exc_info though), so in this PR I'm using it to achieve a behaviour that is fairly close to the default behaviour but with our twist on it. If the naming is an issue, we could totally use extra dictionary instead (also a default thing meant for custom params) and have {"tb_only": False} or "tb_info": True in it or something like that.

I'd better opt to add an extra argument to the exception itself and handle it correctly on the logger.

Now that's a hack 🙂

[ghost]

We NEVER display tracebacks in non-verbose mode, hence why we have all that code in logger.py to handle it. stack_info is a standard mechanism to tell logger to show the stacktrace and it is part of the standard to use it with exc_info in any combination. (see https://docs.python.org/3/library/logging.html#logging.Logger.debug) Our current formatter doesn't process stack_info argument at all(it does use exc_info though), so in this PR I'm using it to achieve a behaviour that is fairly close to the default behaviour but with our twist on it.

@efiop , agree with your comments, your patch solve the problem 🙂

I just felt that it is misleading that we were using stack_info=True but not showing the stack info on --verbose

If we were doing so, the message would be something like: Stack (most recent call last): and the frames would be different.

If the naming is an issue, we could totally use extra dictionary instead (also a default thing meant for custom params) and have {"tb_only": False} in it or something like that.

Isn't extra dict just for formatting? how could you access it?

[ghost]

To summarize, my point is that stack_info is not following the expected behavior, and it is used to mask a message. This is misleading, but it works.
I can't offer a better solution, so I agree with going with the one you suggested.

[efiop]

@MrOutis extra params just become attributes in the log record. You are right about stack_info being cryptic, so I've adjusted my PR to use tb_only instead(could use show_exc_info=False too, let me know if that one sounds better), which does look much nicer to me. Please take a look. 🙂

Stale

[ghost]

Looks good, @efiop ! Thanks for taking it into account 🙂