Silent failure when wrong distribution format

[bayersglassey-zesty]

Your Environment

Thank you for taking the time to report an issue.

To more efficiently resolve this issue, we'd like to know some basic information about your system and setup.

(env) $ uname -a
Linux noo-lappy 5.16.11-76051611-generic #202202230823~1646248261~20.04~2b22243~dev-Ubuntu SMP PREEMPT Th x86_64 x86_64 x86_64 GNU/Linux
(env) $ python --version
Python 3.8.10
(env) $ twine --version
twine version 4.0.0 (importlib-metadata: 4.11.3, keyring: 23.5.0, pkginfo: 1.8.2, requests: 2.27.1, requests-toolbelt: 0.9.1, urllib3: 1.26.9)

I installed twine into a virtualenv with pip install -U twine.
I'm targeting TestPyPi.

The Issue

The twine upload command is silently failing.
It's my fault it's failing: after running python -m build, I wanted to examine the source archive, so I ran gunzip dist/zingest-shared-0.0.1.tar.gz, which transformed it into a TAR file, dist/zingest-shared-0.0.1.tar.
However, twine upload was silently failing because of this:

(env) $ python -m twine upload -r testpypi dist/* || echo "No dice"
Uploading distributions to https://test.pypi.org/legacy/
No dice

...I had to stick a breakpoint in twine/commands/upload.py with ipdb.set_trace() to figure out what the problem was:

> /home/zesty_bag/repos/zestyai/data-ingestion/env/lib/python3.8/site-packages/twine/commands/upload.py(124)upload()
    123 
--> 124     packages_to_upload = [
    125         _make_package(filename, signatures, upload_settings) for filename in uploads

ipdb> 
twine.exceptions.InvalidDistribution: Unknown distribution format: 'zingest-shared-0.0.1.tar'

...that error bubbles up to twine/__main__.py, where there is an attempt to log it, but nothing is output (maybe logging is never configured?):

> /home/zesty_bag/repos/zestyai/data-ingestion/env/lib/python3.8/site-packages/twine/__main__.py(45)main()
     44         error = True
---> 45         logger.error(f"{exc.__class__.__name__}: {exc.args[0]}")
     46 

ipdb> l
     40             f"from {exc.response.url}\n"
     41             f"{exc.response.reason}"
     42         )
     43     except exceptions.TwineException as exc:
     44         error = True
---> 45         logger.error(f"{exc.__class__.__name__}: {exc.args[0]}")
     46 
     47     return error

Steps to Reproduce

1. Go into a Python package
2. Build it with python -m build
3. Turn the source archive into a .tar with gunzip dist/*.gz
4. Attempt to python -m twine upload -r testpypi dist/*

[bayersglassey-zesty]

Ah, I can fix the issue in twine/cli.py by adding the following to the start of configure_output:

    logging.basicConfig(level=logging.WARNING)
    return

...so I guess this is an issue with rich (which is what configure_output is using for the logging handler, specifically rich.logging.RichHandler)?

[bayersglassey-zesty]

...huh, apparently it's because the __main__ logger is disabled:

> /usr/lib/python3.8/logging/__init__.py(1474)error()
   1473         """
-> 1474         if self.isEnabledFor(ERROR):
   1475             self._log(ERROR, msg, args, **kwargs)

ipdb> ll
   1465     def error(self, msg, *args, **kwargs):
   1466         """
   1467         Log 'msg % args' with severity 'ERROR'.
   1468 
   1469         To pass exception information, use the keyword argument exc_info with
   1470         a true value, e.g.
   1471 
   1472         logger.error("Houston, we have a %s", "major problem", exc_info=1)
   1473         """
-> 1474         if self.isEnabledFor(ERROR):
   1475             self._log(ERROR, msg, args, **kwargs)
   1476 

ipdb> self
<Logger __main__ (WARNING)>
ipdb> self.isEnabledFor(ERROR)
False
ipdb> self.disabled
True

[bhrutledge]

Thanks for the detailed report and investigation. It certainly sounds like logging isn't configured properly to catch all scenarios. I'll take a closer look, hopefully within the next week.

[bayersglassey-zesty]

Nice, thank you!

FWIW, following this SO answer to print a message whenever a logger is disabled: https://stackoverflow.com/a/28694704
...I see the following output:

/usr/lib/python3.8/logging/config.py:181 disabled the __main__ logger
/usr/lib/python3.8/logging/config.py:181 disabled the charset_normalizer logger
/usr/lib/python3.8/logging/config.py:181 disabled the requests logger
/usr/lib/python3.8/logging/config.py:181 disabled the rich logger
/usr/lib/python3.8/logging/config.py:181 disabled the urllib3 logger
/usr/lib/python3.8/logging/config.py:181 disabled the urllib3.connection logger
/usr/lib/python3.8/logging/config.py:181 disabled the urllib3.connectionpool logger
/usr/lib/python3.8/logging/config.py:181 disabled the urllib3.poolmanager logger
/usr/lib/python3.8/logging/config.py:181 disabled the urllib3.response logger
/usr/lib/python3.8/logging/config.py:181 disabled the urllib3.util.retry logger
/usr/lib/python3.8/logging/config.py:181 disabled the __main__ logger
/usr/lib/python3.8/logging/config.py:181 disabled the charset_normalizer logger
/usr/lib/python3.8/logging/config.py:181 disabled the requests logger
/usr/lib/python3.8/logging/config.py:181 disabled the rich logger
/usr/lib/python3.8/logging/config.py:181 disabled the urllib3 logger
/usr/lib/python3.8/logging/config.py:181 disabled the urllib3.connection logger
/usr/lib/python3.8/logging/config.py:181 disabled the urllib3.connectionpool logger
/usr/lib/python3.8/logging/config.py:181 disabled the urllib3.poolmanager logger
/usr/lib/python3.8/logging/config.py:181 disabled the urllib3.response logger
/usr/lib/python3.8/logging/config.py:181 disabled the urllib3.util.retry logger

...and the thing at /usr/lib/python3.8/logging/config.py:181 is:

def _handle_existing_loggers(existing, child_loggers, disable_existing):
    """
    When (re)configuring logging, handle loggers which were in the previous
    configuration but are not in the new configuration. There's no point
    deleting them as other threads may continue to hold references to them;
    and by disabling them, you stop them doing any logging.

    However, don't disable children of named loggers, as that's probably not
    what was intended by the user. Also, allow existing loggers to NOT be
    disabled if disable_existing is false.
    """
    root = logging.root
    for log in existing:
        logger = root.manager.loggerDict[log]
        if log in child_loggers:
            if not isinstance(logger, logging.PlaceHolder):
                logger.setLevel(logging.NOTSET)
                logger.handlers = []
                logger.propagate = True
        else:
            logger.disabled = disable_existing

...so the issue seems to be that loggers had already been created (and configured?..) by the time configure_output calls logging.config.dictConfig.

Anyway -- that's enough from me. Thanks for looking into it!

[bhrutledge]

I can reproduce the behavior you described by running python -m twine upload ..., but twine upload ... works as expected:

% python3 -m build
...
Successfully built example-pkg-bhrutledge-0.0.5.tar.gz and example_pkg_bhrutledge-0.0.5-py3-none-any.whl

% gunzip dist/example-pkg-bhrutledge-0.0.5.tar.gz

% twine upload -r testpypi dist/*
Uploading distributions to https://test.pypi.org/legacy/
ERROR    InvalidDistribution: Unknown distribution format: 'example-pkg-bhrutledge-0.0.5.tar'

% twine --version
twine version 4.0.0 (importlib-metadata: 4.10.0, keyring: 23.4.0, pkginfo: 1.8.2, requests: 2.26.0, requests-toolbelt: 0.9.1, urllib3:
1.26.7)

Adding a print of the logger name reveals the difference:

% python -m twine upload -r testpypi dist/*
logger.name='__main__'
Uploading distributions to https://test.pypi.org/legacy/

% twine upload -r testpypi dist/*       
logger.name='twine.__main__'
Uploading distributions to https://test.pypi.org/legacy/
ERROR    InvalidDistribution: Unknown distribution format: 'example-pkg-bhrutledge-0.0.5.tar'    

So, when run as a module, the exception is reported using the __main__ logger, which is disabled in favor of just showing twine logs:

twine/twine/cli.py

Lines 51 to 70 in 4223ee1

	# Using dictConfig to override existing loggers, which prevents failures in
	# test_main.py due to capsys not being cleared.
	logging.config.dictConfig(
	{
	"version": 1,
	"handlers": {
	"console": {
	"class": "rich.logging.RichHandler",
	"show_time": False,
	"show_path": False,
	"highlighter": rich.highlighter.NullHighlighter(),
	}
	},
	"loggers": {
	"twine": {
	"handlers": ["console"],
	},
	},
	}
	)

I'm not sure if that choice was correct. Will explore, and open a PR.