sublack can't start blackd

[abathur]

OS: macos 10.14
sublack: 2.0.1
ST3: build 3180
blackd: 18.9b0

Sublack encounters an error trying to start blackd (regardless of whether it tries to autostart or start via command). If I start blackd externally, sublack is able to use it correctly.

[sublack:server.py](ERROR) blackd not running at localhost on port 45484
Traceback (most recent call last):
  File "/Applications/Sublime Text.app/Contents/MacOS/sublime_plugin.py", line 1072, in run_
    return self.run(edit)
  File "/Users/abathur/Library/Application Support/Sublime Text 3/Installed Packages/sublack.sublime-package/sublack/commands.py", line 120, in run
  File "/Users/abathur/Library/Application Support/Sublime Text 3/Installed Packages/sublack.sublime-package/sublack/server.py", line 124, in run
  File "/Users/abathur/Library/Application Support/Sublime Text 3/Installed Packages/sublack.sublime-package/sublack/server.py", line 107, in _run_blackd
ValueError: read of closed file

Config in case it helps:

{
	"black_command": "/Users/abathur/anaconda/bin/black",
	"black_use_blackd": true,
	"black_py36": true,
	"black_on_save": true,
	"black_blackd_autostart": true
}

[jgirardet]

hi , sorry for trouble.
could you please run it with the 'black_log': 'debug' option to give me the debug messages ?

[abathur]

No worries. (FWIW, just changing the log level didn't do anything until I disabled/enabled the package to force it to reload.)

[sublack:main.py](INFO) Loglevel set to DEBUG
reloading settings Packages/sublack/sublack.sublime-settings
[sublack:commands.py](DEBUG) blackd_start command running
[sublack:utils.py](DEBUG) pyproject path pyproject.toml
[sublack:utils.py](DEBUG) No pyproject.toml file found
[sublack:server.py](DEBUG) New blackdServer instance with params : {'host': 'localhost', 'checker_interval': None, 'settings': {'black_blackd_host': 'localhost', 'black_line_length': None, 'black_skip_string_normalization': False, 'black_use_blackd': True, 'black_skip_numeric_underscore_normalization': False, 'black_fast': False, 'black_command': '/Users/abathur/anaconda/bin/black', 'black_blackd_autostart': True, 'black_exclude': None, 'black_include': None, 'black_log': 'debug', 'black_py36': True, 'black_blackd_port': '45484', 'black_on_save': True, 'black_default_encoding': 'utf-8'}, 'watched': 'plugin_host', 'timeout': 5, 'pid_path': PosixPath('/Users/abathur/Library/Application Support/Sublime Text 3/Cache/sublack/pid'), 'platform': 'osx', 'deamon': True, 'sleep_time': 0.1, 'proc': None, 'port': '45484'}
[sublack:server.py](DEBUG) using /Users/abathur/anaconda/bin/blackd as blackd command
[sublack:server.py](DEBUG) Starting blackd with args ['/Users/abathur/anaconda/bin/blackd', '--bind-port', '45484']
[sublack:server.py](DEBUG) port checked, seems free
[sublack:server.py](ERROR) blackd not running at localhost on port 45484
Traceback (most recent call last):
  File "/Applications/Sublime Text.app/Contents/MacOS/sublime_plugin.py", line 1072, in run_
    return self.run(edit)
  File "/Users/abathur/Library/Application Support/Sublime Text 3/Installed Packages/sublack.sublime-package/sublack/commands.py", line 120, in run
  File "/Users/abathur/Library/Application Support/Sublime Text 3/Installed Packages/sublack.sublime-package/sublack/server.py", line 124, in run
  File "/Users/abathur/Library/Application Support/Sublime Text 3/Installed Packages/sublack.sublime-package/sublack/server.py", line 107, in _run_blackd
ValueError: read of closed file

[jgirardet]

Hi,
The error we see is not the real one logging is broken....
It's fixed on master.
Could you run it from master please so we will see the real error message (seems to occur in the subprocess.Popen(blackd...)

About logging indeed, logging is set in the load_plugin function. I know how to watch for setting change but I do not know the command to reload the plugin on change. If you have any opinion on it, you're welcome ;-)

[abathur]

[sublack:commands.py](DEBUG) blackd_start command running
[sublack:utils.py](DEBUG) No pyproject.toml file found
[sublack:server.py](DEBUG) New blackdServer instance with params : {'port': '45484', 'platform': 'osx', 'timeout': 5, 'sleep_time': 0.1, 'proc': None, 'settings': {'black_py36': True, 'black_blackd_port': '45484', 'black_skip_numeric_underscore_normalization': False, 'black_log': 'debug', 'black_on_save': True, 'black_command': '/Users/abathur/anaconda/bin/black', 'black_default_encoding': 'utf-8', 'black_use_precommit': False, 'black_blackd_autostart': True, 'black_fast': False, 'black_line_length': None, 'black_use_blackd': True, 'black_blackd_host': 'localhost', 'black_skip_string_normalization': False}, 'deamon': True, 'pid_path': Path('/Users/abathur/Library/Application Support/Sublime Text 3/Cache/sublack/pid'), 'host': 'localhost', 'watched': 'plugin_host', 'checker_interval': None}
[sublack:server.py](DEBUG) using /Users/abathur/anaconda/bin/blackd as blackd command
[sublack:server.py](DEBUG) Starting blackd with args ['/Users/abathur/anaconda/bin/blackd', '--bind-port', '45484']
[sublack:server.py](DEBUG) port checked, seems free
[sublack:server.py](ERROR) blackd not running at localhost on port 45484
[sublack:server.py](ERROR) b'blackd start error b'Traceback (most recent call last):\n  File "/Users/abathur/anaconda/bin/blackd", line 11, in <module>\n    sys.exit(main())\n  File "/Users/abathur/anaconda/lib/python3.6/site-packages/click/core.py", line 722, in __call__\n    return self.main(*args, **kwargs)\n  File "/Users/abathur/anaconda/lib/python3.6/site-packages/click/core.py", line 676, in main\n    _verify_python3_env()\n  File "/Users/abathur/anaconda/lib/python3.6/site-packages/click/_unicodefun.py", line 118, in _verify_python3_env\n    \'for mitigation steps.\' + extra)\nRuntimeError: Click will abort further execution because Python 3 was configured to use ASCII as encoding for the environment.  Consult http://click.pocoo.org/python3/for mitigation steps.\n\nThis system lists a couple of UTF-8 supporting locales that\nyou can pick from.  The following suitable locales where\ndiscovered: af_ZA.UTF-8, am_ET.UTF-8, be_BY.UTF-8, bg_BG.UTF-8, ca_ES.UTF-8, cs_CZ.UTF-8, da_DK.UTF-8, de_AT.UTF-8, de_CH.UTF-8, de_DE.UTF-8, el_GR.UTF-8, en_AU.UTF-8, en_CA.UTF-8, en_GB.UTF-8, en_IE.UTF-8, en_NZ.UTF-8, en_US.UTF-8, es_ES.UTF-8, et_EE.UTF-8, eu_ES.UTF-8, fi_FI.UTF-8, fr_BE.UTF-8, fr_CA.UTF-8, fr_CH.UTF-8, fr_FR.UTF-8, he_IL.UTF-8, hr_HR.UTF-8, hu_HU.UTF-8, hy_AM.UTF-8, is_IS.UTF-8, it_CH.UTF-8, it_IT.UTF-8, ja_JP.UTF-8, kk_KZ.UTF-8, ko_KR.UTF-8, lt_LT.UTF-8, nl_BE.UTF-8, nl_NL.UTF-8, no_NO.UTF-8, pl_PL.UTF-8, pt_BR.UTF-8, pt_PT.UTF-8, ro_RO.UTF-8, ru_RU.UTF-8, sk_SK.UTF-8, sl_SI.UTF-8, sr_YU.UTF-8, sv_SE.UTF-8, tr_TR.UTF-8, uk_UA.UTF-8, zh_CN.UTF-8, zh_HK.UTF-8, zh_TW.UTF-8\n''

I guess something in macos mojave or another dependency shift has resurfaced #2?

I checked the Click doc mentioned there to see if there was something painfully obvious I should do. My LANG env is LANG=en_US.UTF-8 and LC_ALL is unset (I tried setting LC_ALL, closing and reopening ST3, but this had no effect).

[jgirardet]

hi,
ok I tried the same fix as #2 via f51c196 on master.
I can't test it here

before trying the fix, you could also try the formatall command which should also fail before the fix.

[abathur]

I tried formatall, but it claimed it ran fine. I saw nothing in the console after running it. I pulled master and it looks like it managed to start the server, though it did produce an additional error:

[sublack:commands.py](DEBUG) blackd_start command running
[sublack:utils.py](DEBUG) No pyproject.toml file found
[sublack:server.py](DEBUG) New blackdServer instance with params : {'settings': {'black_blackd_autostart': True, 'black_on_save': True, 'black_command': '/Users/abathur/anaconda/bin/black', 'black_blackd_port': '45484', 'black_blackd_host': 'localhost', 'black_py36': True, 'black_use_blackd': True, 'black_line_length': None, 'black_skip_string_normalization': False, 'black_default_encoding': 'utf-8', 'black_use_precommit': False, 'black_fast': False, 'black_skip_numeric_underscore_normalization': False, 'black_log': 'debug'}, 'checker_interval': None, 'port': '45484', 'watched': 'plugin_host', 'deamon': True, 'platform': 'osx', 'host': 'localhost', 'timeout': 5, 'pid_path': Path('/Users/abathur/Library/Application Support/Sublime Text 3/Cache/sublack/pid'), 'sleep_time': 0.1, 'proc': None}
[sublack:server.py](DEBUG) using /Users/abathur/anaconda/bin/blackd as blackd command
[sublack:server.py](DEBUG) Starting blackd with args ['/Users/abathur/anaconda/bin/blackd', '--bind-port', '45484']
[sublack:server.py](DEBUG) port checked, seems free
[sublack:server.py](INFO) blackd running at localhost on port 45484 with pid None
[sublack:server.py](DEBUG) BlackdServer started on port 45484 with pid 34250
[sublack:server.py](DEBUG) Running checker with args ['python3', 'checker.py', 'plugin_host', '34250']
Traceback (most recent call last):
  File "/Applications/Sublime Text.app/Contents/MacOS/sublime_plugin.py", line 1072, in run_
    return self.run(edit)
  File "/Users/abathur/Library/Application Support/Sublime Text 3/Packages/sublack/sublack/commands.py", line 121, in run
    started = sv.run()
  File "/Users/abathur/Library/Application Support/Sublime Text 3/Packages/sublack/sublack/server.py", line 143, in run
    self.checker = popen(checker_cmd, cwd=cwd)
  File "./python3.3/subprocess.py", line 819, in __init__
  File "./python3.3/subprocess.py", line 1448, in _execute_child
FileNotFoundError: [Errno 2] No such file or directory: 'python3'

[jgirardet]

Hi,

I tried formatall, but it claimed it ran fine. I saw nothing in the console after running it.
this click bug is very strange 🤔

I pulled master and it looks like it managed to start the server,
cool

though it did produce an additional error:

checker.py is a small script which watch if sublime is still running to shutdown blackd server when exiting sublimetext.

I do not use python but python because it's a python3 script and many system still have default python as python2 interpreter. It was ok on CI so I thought it was good.

On your system maybe due to mojave or anaconda, there is no python3 in the path.

I'll think to it.

thank you for all your feedback

[abathur]

Hmm. I do have python3 on the system path:

$ which python3 && python3 --version
/Users/abathur/anaconda/bin/python3
Python 3.6.1 :: Anaconda 4.4.0 (x86_64)
$ which python && python --version
/Users/abathur/anaconda/bin/python
Python 3.6.1 :: Anaconda 4.4.0 (x86_64)
$ which python2 && python2 --version
/usr/local/bin/python2
Python 2.7.5

But I guess it's not the same within ST3's local python. In the ST3 console:

>>> os.environ['PATH']
'/usr/bin:/bin:/usr/sbin:/sbin'

Running the same in an external python returns the full system path.

[jgirardet]

hi,
I added something with different ways to find a python3 executable. I hope one should fit.
It's on master

[abathur]

I'll start at the end: We're getting somewhere! It looks like this is a common issue lately, and it doesn't seem like there's anything wrong with how you're trying to use subprocess here. (On the downside, it looks like these edits were mostly a waste of your time.)

I tried your master and still had the same no-such-file-or-directory issue. I've been feeling bad about sending you on a wild goose chase (I know how frustrating it is to try and debug something only cropping up on a platform you don't have access to), so I spent a while searching github and ST3 forums and eventually stumbled into a GH issue (SublimeLinter/SublimeLinter#1508) for SublimeLinter that started to peel back what seems to be going on. Since then, I've found quite a lot of these threads around.

While supposedly these macos path issues had been fixed in an earlier release, it seems like that fix depends on your shell startup running in under 1s. The common workaround cited in these threads is launching ST3 from the command line (i.e., with subl, in which case it inherits the environment). This workaround is fine for me (I don't want to get tricked into wasting a day fiddling with shell launch time at the moment :D ).

I suppose it may help to document the issue. If you get more issues on the topic, I guess you could also detect when the path is the default and log to console or open a dialog pointing the user toward a fix that doesn't waste more of your time :).

I'm tempted to close this, but I'll defer to whether you feel like leaving it open will help avoid others opening similar issues.

[jgirardet]

Hi,
that was a huge answer !! thanks for taking the time.
I can now point users to this fix which i already a good thing.
Wasting my time wasn't a big deal since coding is not my job, just a hobby ;-)

Anyway the only thing which hurts me is that the last fix should have worked:

def get_python3_executable(config=None):

    # First check for python3/python in path
    for version in ["python3", "python"]:
        if is_python3_executable(version):
            return version

    # Then find  one via shell
    python_exec = find_python3_executable()
    if python_exec:
        return python_exec

    # Third: guess from black_command
    if config:
        if config["black_command"] != "black":
            python_exec = str(Path(config["black_command"]).parent / "python")
            print(python_exec)

            if is_python3_executable(python_exec):
                return python_exec

    return False

After the 2 first parts fail on your system, the last one should have guess /Users/abathur/anaconda/bin/python since your black_command points to /Users/abathur/anaconda/bin/black.

after checking, the second part might raise an exception I didn't catch. I fixed it and reordered it (now the black_command way comes second.

I really like this work since It would be, I think, easier to say to users : "there is a problem with your path, please enter the full path of black_command to fix it" and that's it.

[abathur]

Ok.

I don't mind trying more versions if you'd like to keep searching for a fix. Here's_ the current stack:

[sublack:commands.py](DEBUG) blackd_start command running
[sublack:utils.py](DEBUG) No pyproject.toml file found
[sublack:server.py](DEBUG) New blackdServer instance with params : {'platform': 'osx', 'port': '45484', 'checker_interval': None, 'proc': None, 'deamon': True, 'watched': 'plugin_host', 'settings': {'black_line_length': None, 'black_py36': True, 'black_blackd_autostart': True, 'black_fast': False, 'black_log': 'debug', 'black_on_save': True, 'black_use_blackd': True, 'black_skip_string_normalization': False, 'black_skip_numeric_underscore_normalization': False, 'black_blackd_port': '45484', 'black_command': '/Users/abathur/anaconda/bin/black', 'black_blackd_host': 'localhost', 'black_use_precommit': False, 'black_default_encoding': 'utf-8'}, 'host': 'localhost', 'pid_path': Path('/Users/abathur/Library/Application Support/Sublime Text 3/Cache/sublack/pid'), 'timeout': 5, 'sleep_time': 0.1}
[sublack:server.py](DEBUG) using /Users/abathur/anaconda/bin/blackd as blackd command
[sublack:server.py](DEBUG) Starting blackd with args ['/Users/abathur/anaconda/bin/blackd', '--bind-port', '45484']
[sublack:server.py](DEBUG) port checked, seems free
[sublack:server.py](INFO) blackd running at localhost on port 45484 with pid None
[sublack:server.py](DEBUG) BlackdServer started on port 45484 with pid 2790
Traceback (most recent call last):
  File "/Applications/Sublime Text.app/Contents/MacOS/sublime_plugin.py", line 1072, in run_
    return self.run(edit)
  File "/Users/abathur/Library/Application Support/Sublime Text 3/Packages/sublack/sublack/commands.py", line 121, in run
    started = sv.run()
  File "/Users/abathur/Library/Application Support/Sublime Text 3/Packages/sublack/sublack/server.py", line 138, in run
    python_executable = get_python3_executable(self.settings)
  File "/Users/abathur/Library/Application Support/Sublime Text 3/Packages/sublack/sublack/utils.py", line 371, in get_python3_executable
    python_exec = find_python3_executable()
  File "/Users/abathur/Library/Application Support/Sublime Text 3/Packages/sublack/sublack/utils.py", line 343, in find_python3_executable
    "which python3", shell=True, executable=default_shell
  File "./python3.3/subprocess.py", line 589, in check_output
subprocess.CalledProcessError: Command 'which python3' returned non-zero exit status 1

I do wonder if it's possible to reproduce the problem in a CI run, since that might shorten the experiment loop. I guess since it's running from command line it probably inherits the env set by travis-ci and the .travis.yml; maybe it's as simple as fiddling with the path.

[jgirardet]

Ok.

I don't mind trying more versions if you'd like to keep searching for a fix. Here's_ the current stack:

no, I don't mind asking you to do it 😄

indeed my curiosity might bring me some pain in CI soon 😆

I let it open for now, I'll close it if i'm sure to have a fix.

nice sunday

[jgirardet]

should be fixed in 2.1.0 🤞

[abathur]

Gave this a try today, figured I should post in case it's useful.

Log:

[sublack:main.py](INFO) Loglevel set to DEBUG
[sublack:commands.py](DEBUG) blackd_start command running
[sublack:utils.py](DEBUG) No pyproject.toml file found
[sublack:server.py](DEBUG) New blackdServer instance with params : {'port': '45484', 'proc': None, 'watched': 'plugin_host', 'sleep_time': 0.1, 'deamon': True, 'pid_path': Path('/Users/abathur/Library/Application Support/Sublime Text 3/Cache/sublack/pid'), 'timeout': 5, 'platform': 'osx', 'settings': {'black_on_save': True, 'black_blackd_port': '45484', 'black_blackd_autostart': True, 'black_py36': True, 'black_log': 'debug', 'black_blackd_host': 'localhost', 'black_default_encoding': 'utf-8', 'black_use_precommit': False, 'black_command': '/Users/abathur/anaconda/bin/black', 'black_fast': False, 'black_skip_numeric_underscore_normalization': False, 'black_use_blackd': True, 'black_skip_string_normalization': False, 'black_line_length': None}, 'checker_interval': None, 'host': 'localhost'}
[sublack:server.py](DEBUG) using /Users/abathur/anaconda/bin/blackd as blackd command
[sublack:server.py](DEBUG) Starting blackd with args ['/Users/abathur/anaconda/bin/blackd', '--bind-port', '45484']
[sublack:server.py](DEBUG) port checked, seems free
[sublack:server.py](INFO) blackd running at localhost on port 45484 with pid None
[sublack:server.py](DEBUG) BlackdServer started on port 45484 with pid 3168
[sublack:server.py](DEBUG) pid cache updated to "3168"
[sublack:utils.py](ERROR) is_python3_executable : FileNotFoundError Command 'python3 --version' returned non-zero exit status 127
[sublack:utils.py](DEBUG) python is not a python3 executable
[sublack:utils.py](DEBUG) /usr/bin/python is not a python3 executable
[sublack:utils.py](DEBUG) /Users/abathur/anaconda/bin/python is not a python3 executable
[sublack:utils.py](DEBUG) no valid python3 interpreter was found
[sublack:server.py](DEBUG) python_executable found : False
error: Sublack: Checker didn't start successfull.You will have to run manually Stop Blackd before leaving sublime_text to stop blackd. you can set 'black_log' to 'debug', and add an issue to sublack to help fix itThis maybe related to https://github.com/jgirardet/sublack/issues/35

Not sure about the python3 interpreter test above:

$ /Users/abathur/anaconda/bin/python --version
Python 3.6.1 :: Anaconda 4.4.0 (x86_64)

The error at the end did show up in a dialog as well:

[jgirardet]

It never ends, damn.... I'm really sorry I really thought I would work.
At least , the path is found which is already a good thing 😢

The log seems to say that the following return True :

if not version_out or version_out[7] != "3":
        LOG.debug("%s is not a python3 executable", python_executable)
        return False

version_out = subprocess.check_output('/python/version --version', shell=True)

which is strange : how version_out could be False ?

The only thing I could reproduce is on a python2 interpreter if is a different behavior between python2 and 3 :

In [21]: subprocess.check_output('python3 --version', shell=True)
Out[21]: b'Python 3.7.0\n'

In [22]: subprocess.check_output('python2.7 --version', shell=True)
Python 2.7.15rc1
Out[22]: b''

I changed version detection to

 find_version = '{} -c "import sys;print(sys.version_info.major)"'.format(python_executable)

I let it opened for now

[abathur]

Also possible that Sublime's internal 3.3 python is complicating things if there are any differences. I'm not certain why this is mattering, but I fiddled with those statements a bit in ST3 console. I'll show a few things that didn't work, and the first one that did. :)

>>> subprocess.check_output('/Users/abathur/anaconda/bin/python --version')
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "./python3.3/subprocess.py", line 576, in check_output
  File "./python3.3/subprocess.py", line 819, in __init__
  File "./python3.3/subprocess.py", line 1448, in _execute_child
FileNotFoundError: [Errno 2] No such file or directory: '/Users/abathur/anaconda/bin/python --version'

I haven't gotten curious enough to dig into how and why they differ, but I've noticed I often run into subprocess examples that use a full command with flags in a single string, but the current python docs use an array, so I tried this first:

>>> subprocess.check_output(['/Users/abathur/anaconda/bin/python', '--version'])
b''

Since it seemed to run but produced no output, I was curious if there would be an error message on stderr...

>>> subprocess.check_output(['/Users/abathur/anaconda/bin/python', '--version'], stderr=subprocess.STDOUT)
b'Python 3.6.1 :: Anaconda 4.4.0 (x86_64)\n'

[abathur]

That said, I think the statement you ended on is probably a better approach. I didn't notice it at first, but I was about to suggest the same thing. I tried this in ST3 console as well:

This wouldn't work:

>>> subprocess.check_output('/Users/abathur/anaconda/bin/python -c "import sys;print(sys.version_info.major)"')
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "./python3.3/subprocess.py", line 576, in check_output
  File "./python3.3/subprocess.py", line 819, in __init__
  File "./python3.3/subprocess.py", line 1448, in _execute_child
FileNotFoundError: [Errno 2] No such file or directory: '/Users/abathur/anaconda/bin/python -c "import sys;print(sys.version_info.major)"'

But this does:

>>> subprocess.check_output(['/Users/abathur/anaconda/bin/python', '-c', 'import sys;print(sys.version_info.major)'])
b'3\n'

[jgirardet]

to use plain string in subprocess instead of list, you have to use shell=True.
I used here shell=True, to "limit" env matters due to some config un .bashrc, .profile....

[abathur]

Aha; I didn't realize shell had an effect beyond the env issues. Good to know. :)

[jgirardet]

I pushed 2.1.1 with the fix