YCM runs on large-ish non-source files, spews a backtrace when you enter insert mode

[jlebar]

STR:

# Create a file that's large, but not so large as to cause ycm to disable itself
$ cd `mktemp -d`
$ dd if=/dev/urandom of=test bs=500k count=1
$ vim test

Now enter insert mode.

Result: YCM error spew, included below.

I bisected the test file size and noticed that the error starts occurring somewhere between files of size 100k and 300k.

Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/usr/lib/youcompleteme/autoload/../python/ycm/youcompleteme.py",
line 255, in NativeFiletypeCompletionUsable
    self.NativeFiletypeCompletionAvailable() )
  File "/usr/lib/youcompleteme/autoload/../python/ycm/youcompleteme.py",
line 250, in NativeFiletypeCompletionAvailable
    vimsupport.CurrentFiletypes() ] )
  File "/usr/lib/youcompleteme/autoload/../python/ycm/youcompleteme.py",
line 240, in FiletypeCompleterExistsForFiletype
    exists_completer = SendCompleterAvailableRequest( filetype )
  File "/usr/lib/youcompleteme/autoload/../python/ycm/client/completer_available_request.py",
line 57, in SendCompleterAvailableRequest
    request.Start()
  File "/usr/lib/youcompleteme/autoload/../python/ycm/client/completer_available_request.py",
line 45, in Start
    'semantic_completion_available' )
  File "/usr/lib/youcompleteme/autoload/../python/ycm/client/base_request.py",
line 81, in PostDataToHandler
    timeout ) )
  File "/usr/lib/youcompleteme/autoload/../python/ycm/client/base_request.py",
line 177, in JsonFromFuture
    _ValidateResponseObject( response )
  File "/usr/lib/youcompleteme/autoload/../python/ycm/client/base_request.py",
line 206, in _ValidateResponseObject
    their_hmac = ToBytes( b64decode( response.headers[ _HMAC_HEADER ] ) )
  File "/usr/lib/youcompleteme/third_party/ycmd/third_party/requests/requests/structures.py",
line 54, in __getitem__
    return self._store[key.lower()][1]
KeyError: u'x-ycm-hmac'
E858: Eval did not return a valid python object

+@r4nt

[vheon]

I expected this to happen when the file is around 1Mb, which is the max size of a request that we set for Bottle, but if you can reproduce this with a 500Kb then the problem could be something else 😕 Can you post the ycmd logs as well?

[jlebar]

Sure, where can I find the ycmd logs?

[puremourning]

:YcmDebugInfo

[jlebar]

OK, looks just like the stack trace I got above.

Printing YouCompleteMe debug information...
Error detected while processing function <SNR>149_DebugInfo[2]..<SNR>149_Pyeval:
line    2:
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/usr/lib/youcompleteme/autoload/../python/ycm/youcompleteme.py", line 550, in DebugInfo
    'debug_info' )
  File "/usr/lib/youcompleteme/autoload/../python/ycm/client/base_request.py", line 81, in PostDataToHandler
    timeout ) )
  File "/usr/lib/youcompleteme/autoload/../python/ycm/client/base_request.py", line 177, in JsonFromFuture
    _ValidateResponseObject( response )
  File "/usr/lib/youcompleteme/autoload/../python/ycm/client/base_request.py", line 206, in _ValidateResponseObject
    their_hmac = ToBytes( b64decode( response.headers[ _HMAC_HEADER ] ) )
  File "/usr/lib/youcompleteme/third_party/ycmd/third_party/requests/requests/structures.py", line 54, in __getitem__
    return self._store[key.lower()][1]
KeyError: u'x-ycm-hmac'
E858: Eval did not return a valid python object
-- 0

[vheon]

Actually the command didn't work an you got the same error as before. What you shoul do is:

• open the "big" file with vim
• use YcmDebugInfo to get the path of ycmd logs file
• Enter Insert mode to get the error
• Post the log

[jlebar]

• open the "big" file with vim
• use YcmDebugInfo to get the path of ycmd logs file

If I do this, I still get the same stacktrace.

OTOH if I invert the order of these operations, I get the following in my stderr log. The stdout log is empty.

2016-05-05 14:23:55,847 - INFO - Calling global extra conf method YcmCorePreload on conf file /usr/lib/youcompleteme/ycm_extra_conf.py
2016-05-05 14:23:57,138 - INFO - Received health request
2016-05-05 14:23:57,141 - INFO - Received debug info request
2016-05-05 14:24:30,079 - INFO - Received filetype completion available request

[Valloric]

@jlebar Since I see references to /usr/lib/youcompleteme/, could you make sure you can repro this with vanilla YCM and not the Google-internal copy?

[jlebar]

I wonder if I'm saving anyone time by doing all this testing myself? Like, if others cannot reproduce, I would be happy to dig in and try to figure out what is interesting about my config, but otherwise if I can reproduce using the public build, well, the next step is going to be for someone else to reproduce it themselves...

Unless you think this is likely to be something unusual about my config?

[Valloric]

Like, if others cannot reproduce, I would be happy to dig in and try to figure out what is interesting about my config

By all means, please do. :)

otherwise if I can reproduce using the public build, well, the next step is going to be for someone else to reproduce it themselves...

True, but issue reporters are rarely willing to run through the code to figure out the issue. :)

Also, we tend to know the codebase pretty well. If we could repro it, we could probably figure out the root cause faster and with less hassle. But hey, if you're willing to dig through the code on this, count us happy. :)

[jlebar]

I'm not sure where you got that I was volunteering to dig through the code? Sorry, I must have been unclear.

All I was asking is for someone else to try to reproduce this bug, before asking me to spend half an hour configuring YCM on a new machine. If that's too much to ask, I'll go away, with sincere apologies for wasting everyone's time.

[r4nt]

I can repro with stock YCM on my mac at head. Exact same behavior. Server stderr:
tail -f /var/folders/4l/w5dybvgs0790k5d3x6856drw002dvz/T/ycm_temp/server_56305_stderr.log
2016-05-06 16:28:06,488 - INFO - Received health request
2016-05-06 16:28:06,492 - INFO - Received debug info request
2016-05-06 16:28:37,967 - INFO - Received filetype completion available request

Otherwise the exact same output as @jlebar.

:YcmDebugInfo
Printing YouCompleteMe debug information...
-- Server has Clang support compiled in: False
-- Server running at: http://127.0.0.1:56341
-- Server process ID: 73697
-- Server logfiles:
-- /var/folders/4l/w5dybvgs0790k5d3x6856drw002dvz/T/ycm_temp/server_56341_stdout.log
-- /var/folders/4l/w5dybvgs0790k5d3x6856drw002dvz/T/ycm_temp/server_56341_stderr.log

[vheon]

I'll look into this