Hhvm: hh_client hangs on OSX, but works if killed and retried

[ssandler]

HHVM Version

hhvm --version
HipHop VM 3.28.1-0-slack (rel)
Compiler: 1536019668_N
Repo schema: 67f5fcde7bddd6a0837c7f2e1ec04a5e6fee91f2

Operating System and Version

MacOS High Sierra, notably this does NOT reproduce on Debian.

Standalone code, or other way to reproduce the problem

This only reproduces when running hh_client on a large repository. Small repositories work fine. Ours is much smaller than FB's www I'm sure, about 2M LOC.

Actual result

hh_client hangs until it runs out of retries or you ctrl+c it. Subsequent runs of hh_client work just fine, and report the expected result. It takes several minutes to run out of retries, far longer than the 22 seconds the server spends getting ready from these logs.

$ hh_client
For more detailed logs, try `tail -f $(hh_client --monitor-logname) $(hh_client --logname)`
Server launched with the following command:
    '/usr/local/Cellar/[email protected]/3.28.1/bin/hh_server' '-d' '/Users/ssandler/Documents/dev/webapp' '--waiting-client' '5'
Spawned typechecker (child pid=96900)
Logs will go to /private/tmp/hh_server/monitor_logs/zSUserszSssandlerzSDocumentszSdevzSwebapp-2018-09-18-14-15-02.monitor_log
hh_server is busy: [processing] /
Error: Ran out of retries, giving up!


$ cat $(hh_client --monitor-logname)
[2018-09-18 14:15:02.264] Loading config exception: (Sys_error "/usr/local/etc/hh.conf: No such file or directory")
[2018-09-18 14:15:02.264] Could not load config at /usr/local/etc/hh.conf, using defaults
Informant using dummy - resigning
[2018-09-18 14:15:02.331] Starting first server
[2018-09-18 14:15:02.332] About to spawn typechecker daemon. Logs will go to /private/tmp/hh_server/zSUserszSssandlerzSDocumentszSdevzSwebapp.log

[2018-09-18 14:15:02.334] Just started typechecker server with pid: 96902.
[2018-09-18 14:15:03.336] Got default request for typechecker. Prior request 1.0 seconds ago

$ cat $(hh_client --logname)
[2018-09-18 14:15:02.472] Loading config exception: (Sys_error "/usr/local/etc/hh.conf: No such file or directory")
[2018-09-18 14:15:02.472] Could not load config at /usr/local/etc/hh.conf, using defaults
[2018-09-18 14:15:02.473] Version: hh-d79571c59fd56e173cb616b9df2083a600a1635a-3.28.1 Mon Sep  3 17:08:47 2018
[2018-09-18 14:15:02.473] Hostname: SFO-M-SSANDLER01.local
[2018-09-18 14:15:02.479] Loading config exception: (Sys_error "/usr/local/etc/hh.conf: No such file or directory")
[2018-09-18 14:15:02.479] Could not load config at /usr/local/etc/hh.conf, using defaults
[2018-09-18 14:15:02.492] Initializing Server (This might take some time)
[2018-09-18 14:15:02.493] Init id: kx3Z5lE3DQ
[2018-09-18 14:15:02.493] Initing with approach: Local_config_mini_state_disabled
[2018-09-18 14:15:02.493] Begin Indexing
[2018-09-18 14:15:02.493] Indexing: 0.000002
[2018-09-18 14:15:02.493] Begin Parsing
[2018-09-18 14:15:14.323] Heap size: 129075968
[2018-09-18 14:15:14.323] Parsing: 11.830879
[2018-09-18 14:15:14.357] Updating deps: 0.033804
[2018-09-18 14:15:14.357] Begin Naming
[2018-09-18 14:15:14.488] Heap size: 136360832
[2018-09-18 14:15:14.488] Naming: 0.130369
[2018-09-18 14:15:15.040] Updating 9169 search files:: 0.535844
[2018-09-18 14:15:15.040] Done updating search files
[2018-09-18 14:15:15.045] Dependency table load factor: 0 / 1048576 (0.00)
[2018-09-18 14:15:15.047] Hashtable load factor: 147028 / 1048576 (0.14) with 147028 nonempty slots
[2018-09-18 14:15:15.047] Waiting for daemon(s) to be ready...
[2018-09-18 14:15:15.047] Server is partially ready
[2018-09-18 14:15:15.047] Took 12.554565 seconds.
******************************************
[2018-09-18 14:15:15.047] Check kind: Full_check
[2018-09-18 14:15:15.047] Files to recompute: 0
[2018-09-18 14:15:15.047] Begin Parsing 0 files
[2018-09-18 14:15:15.048] Heap size: 144006656
[2018-09-18 14:15:15.048] Parsing 0 files: 0.000673
[2018-09-18 14:15:15.048] Begin Updating deps
[2018-09-18 14:15:15.048] Updating deps: 0.000020
[2018-09-18 14:15:15.048] Begin Naming
[2018-09-18 14:15:15.048] Naming: 0.000020
[2018-09-18 14:15:15.048] Heap size: 144006656
[2018-09-18 14:15:15.048] Determining changes: 0.000508
[2018-09-18 14:15:15.048] Begin Type-decl 0 files
[2018-09-18 14:15:15.049] Heap size: 144006656
[2018-09-18 14:15:15.049] Type-decl 0 files: 0.000477
[2018-09-18 14:15:15.073] Begin Type-check 9168 files
[2018-09-18 14:15:25.313] Type-check 9168 files: 10.263725
[2018-09-18 14:15:25.313] Total: 10.265423

[2018-09-18 14:15:25.314] Dependency table load factor: 469559 / 1048576 (0.45)
[2018-09-18 14:15:25.316] Hashtable load factor: 231057 / 1048576 (0.22) with 231057 nonempty slots
[2018-09-18 14:15:25.316] Heap size: 164081792
[2018-09-18 14:15:25.316] Server is READY
[2018-09-18 14:15:25.316] Took 22.823757 seconds to initialize.
[2018-09-18 14:15:25.317] Recheck id: Fsu3e7g8wo
Error: End_of_file

Expected result

hh_client will detect when the server is ready and report results.

[juanfernandoe]

+1

Same sitation here.

[ssandler]

I wanted to see if this repro'd on nightlies, since I've seen some commits to master which might be related to this issue, such as https://github.com/facebook/hhvm/commit/3debfddf0e365b493e4b917e5d48bf9446e969b3.

It does still repro on today's nightlies, but the behavior is a little different. The nightlies have a progress indicator that lists the % of files which are checked. Once that hits 100%, running hh_client in a separate terminal will yield results, but the process which launched hh_client hangs and goes back to "Processing". Eventually, instead of "Ran out of retries, giving up!" we see:

hh_server is busy: [processing] -Uncaught exception:

  Unix.Unix_error(Unix.EMFILE, "socket", "")

Raised at file "src/core/lwt.ml", line 2987, characters 20-29
Called from file "src/unix/lwt_main.ml", line 26, characters 8-18
Called from file "src/hh_client.ml", line 68, characters 10-51

This only happens on OSX - on linux it returns results after reaching 100%.

[fredemmott]

happens with all editors closed and all hh_server/hhvm processes killed before reproing

[jeffomatic]

A few observations so far:

1. It appears that the initial connection to a cold-start hh_server seems to fail on the STATUS RPC. I've been testing this against the Slack monorepo, which means that the typecheck takes quite some time before any RPC is attempted. I just had the idea to try it on a nearly-empty project, to see if it might be a timing issue.

2. Simply re-establishing the connection during the client-check RPC call "solves" the issue:

   rpc args command (fun conn_f command ->
     let%lwt _ = conn_f () in
     let%lwt conn = conn_f () in (* intentional repetition *)
     let%lwt result = ClientConnect.rpc conn command in
     Lwt.return result
   )
   

   Obviously, this isn't a real solution, but it does seem to indicate that the initial connection goes stale somehow.

3. Moments after the initial typecheck completes, the server logs show a thrown exception. It occurs after delivering a hello to the client, during the server's attempt to call read_connection_type on the input channel from the client:

   Error: End_of_file
   RAISED AT=Raised by primitive operation at file "src/utils/sys/timeout.ml", line 64, characters 8-33
   Called from file "src/utils/sys/timeout.ml", line 33, characters 12-18
   Re-raised at file "src/utils/sys/timeout.ml", line 38, characters 10-49
   Called from file "src/server/serverClientProvider.ml", line 108, characters 6-29
   Called from file "src/server/serverMain.ml", line 205, characters 10-52
   Called from file "src/server/serverMain.ml", line 190, characters 4-8
   

   It's possible that the "thread" representing the initial connection dies on this before any RPC can be made, and it does so without crashing the hh_server process (and thus leaving the output fd hanging open). One possible cause is the client prematurely closing the output fd on its side of the connection, but I haven't yet discovered if/where this is happening.

4. Tangentially, I noticed that connect_to_monitor_and_get_server_progress appears to leak file descriptors. It is likely that we can get away with simply closing the input channel as soon as we've read from it. Because hh_client maintains a broad timeout, the leak probably doesn't cause a real issue, but it seems worth closing as a matter of hygiene.

[jeffomatic]

A bit more: it does seem like 72ab5ddc78e already hit on the basic concern, which is that MacOS does not provide a graceful handoff of the client connection from server monitor (parent) to the server "main" (child).

As an example, try an adjustment to Sent_fds_collector.cleanup_fd so that it simply waits a duration that exceeds the long initial typecheck phase:

  let cleanup_fd fd =
    if Sys_utils.is_apple_os () then
      (** CHANGE DELAY to something really long. I need ~60 seconds for my test case *)
      let trigger = Unix.gettimeofday () +. 80.0 in
      Fd_scheduler.wait_for_fun
        ~once:true
        ~priority:1
        (fun time -> time >= trigger)
        (fun x ->
          let () = Printf.eprintf "Closing client fd\n" in
          let () = Unix.close fd in x)
    else
      Unix.close fd

Adjusting the delay from 2 seconds to 80 seconds prevents the hang in my test case. hh_client terminates successfully.

What's a bit curious is that even without this tweak, the post-handoff connection seems to be okay for writes from server back to client (the client will successfully receive a server hello after a very long initial typecheck), but it will fail due to EOF if we _read_ from the connection. In other words, the server will hit an exception when reading the connection type after sending hello over what is ostensibly the same connection. I believe the input/output channels refer to the same fd, which seems to imply a kernel quirk that exists beneath the file abstraction layer.

I'm not sure if I know enough about the underlying kernel implementation to recommend a proper fix, but I can think of a few hacks, including:

• Having hh_client remember if it had to start the server, and if so, open a fresh connection after receiving the server hello. This still may cause leaks on the server side, because there's a server thread stalled on the EOF exception.
• Not closing the server monitor's copy of the fd, ever. I suspect this may cause the actual connection to never get collected by the kernel until all three of the client, server, and server monitor all close.
• If the above bothers us, but we are okay with the fds getting cleaned up after a long wait, we could also set a very large cleanup delay in Sent_fds_collector.cleanup_fd, so that all use cases are effectively addressed. Say, an hour.
• Orchestrating a dummy write from server back to client early on, between the monitor-server handoff and the initial typecheck phase. I haven't tried this, but I have a wild guess that this will keep the connection fresh.

These could be quarantined as Mac-only adjustments. Even still, I wonder how palatable any of these approaches seem to the HHVM team?

[ljw1004]

@jeffomatic Thanks for the detailed analysis. This is a crummy area and I totally agree the monitor handoff is poor.

Here's the approach that the hack team at Facebook has been working on:

1. Rewrite hh_client to be independent of hh_server. @arxanas has been working on this for several months so far. The idea is that hh_client will be able to handle all per-file LSP requests for the currently open documents (autocomplete, hover, error squiggles, ...) without any need for the server.
2. Rewrite hh_server a bit. It will no longer monitor watchman for changes. It will maintain in memory a dependency graph. When you do "hh check" it will ask watchman which files have changed since it was last invoked, it will figure out from the dependency graph what has to be rechecked, and it will trigger a bulk typecheck of those files, which gets shown on stdout.
3. As a completely separate standalone thing we'll have a file-watcher, like VSCode's "continuous" build watching. When you start this, then every time a file changes then it will invoke "hh check".

The idea is to simplify it all, get rid of the monitor-client communication, get rid of the client-server communication, and be more like VSCode convention. We'll have a bog standard VSCode build task, one for a one-off build (which invokes "hh check") and one for a continuous watch (which launches the watcher). Those builds will always output into stdout, which gets scraped to populate the diagnostics list.

We think we can have prototypes working near the end of 2019, and to roll it out fully in the first quarter of 2020. These changes would obviate the need for fixes.

(There are two LSP requests that aren't per-file. These are "show me the autocomplete list of all top-level symbols" and "find all references/implementations". We expect to implement the autocomplete list by building a sqlite database in the background of symbols. We expect to implement find-all-references/implementations using the same kind of logic as "hh check" since it has to do essentially the same work.)

@jeffomatic you suggested some hacks. I think we have a high tolerance for mac-only temporary hacks that will become obviated in 6-9 months!

For your hacks 2 and 3 ("not closing monitor's fd ever" or "closing after a long delay") - won't the monitor end up accumulating fds for ages? like, every single time someone does "hh check" then it will be a new monitor fd? I can imagine easily doing hundreds hh checks so that fds become exhausted. I have a vague memory of somewhere else in the code deliberately requiring an fd number <1024, but I might be mistaken. I can't think of a nice way to distinguish which fds need to be kept open for ages and which don't.

It feels like hack 1 ("open fresh connection after receiving server hello") sounds the neatest smallest fix.

[jeffomatic]

It feels like hack 1 ("open fresh connection after receiving server hello") sounds the neatest smallest fix.

Sounds good. One disadvantage of this tactic is that I'm not sure if this results in a resource leak within the server main...it seems like the client-side hang is directly caused by a server-side dangling lwt context that died on an exception. Of course, this might be an infrequent thing, so maybe it's not so bad unless hh_server has been running for a long time.

Here's one strategy, in pseudocode:

let rpc ... =
    let start = time () in
    let conn = conn_f () in
    (* refresh the connection if on MacOS and getting a hello took a long time *)
    let conn = if apple? () and (time () - start > two seconds) conn_f () else conn in
    ...

I'm hoping this will cover any case where hh_server is not responding to RPCs for a lengthy period of time, either due to cold start or a large change in the working tree.

won't the monitor end up accumulating fds for ages?

Sounds about right! Tangentially, I mentioned above that the _client_ leaks fds when it polls the monitor for the progress spinner. If that sounds like a concern, I can submit a separate PR that plugs the leak.

[xixixao]

Just noting I just got this on MacOS 10.14.6 (Mojave).

[mkstarr]

Hi. Willing to help but don't know what an hh client is. Link?