reveal_type does not work reliably

[cyounkins]

Pysa Bug

Pre-submission checklist
[x] I've checked the list of common issues and mine does not appear

Bug description
One invocation of pyre analyze, reveal_type will print out the type correctly. With no changes to code, the next invocation it will not.

Reproduction steps
Try on my repo: https://github.com/cyounkins/pysa-testing/tree/63395fc6b3ba826b1ebb9dec1c55abcadf4c7622

Expected behavior
reveal_type should always output

Logs
Below are normal logs. Here are some noninteractive: https://gist.github.com/cyounkins/1831c2b62ea8bc5f84852526632ecbee

root@229a900571ee:/usr/src/app# pyre analyze
ƛ  `google.protobuf.message.Message.ClearField` has 57 overrides, this might slow down the analysis considerably.
ƛ  `google.protobuf.message.Message.__init__` has 58 overrides, this might slow down the analysis considerably.
ƛ  `libcst._nodes.base.CSTNode._codegen_impl` has 102 overrides, this might slow down the analysis considerably.
ƛ  `libcst._nodes.base.CSTNode._visit_and_replace_children` has 119 overrides, this might slow down the analysis considerably.
ƛ  `object.__eq__` has 530 overrides, this might slow down the analysis considerably.
ƛ  `object.__hash__` has 115 overrides, this might slow down the analysis considerably.
ƛ  `object.__init__` has 1927 overrides, this might slow down the analysis considerably.
ƛ  `object.__ne__` has 370 overrides, this might slow down the analysis considerably.
ƛ  `object.__repr__` has 176 overrides, this might slow down the analysis considerably.
ƛ  `object.__setattr__` has 52 overrides, this might slow down the analysis considerably.
ƛ  `object.__str__` has 81 overrides, this might slow down the analysis considerably.
ƛ  `pika.amqp_object.Method.synchronous` has 66 overrides, this might slow down the analysis considerably.
ƛ  `type.__call__` has 220 overrides, this might slow down the analysis considerably.
ƛ  `type.__init__` has 1674 overrides, this might slow down the analysis considerably.
ƛ  `type.__new__` has 294 overrides, this might slow down the analysis considerably.
ƛ  `type.__or__` has 53 overrides, this might slow down the analysis considerably.
ƛ  `typing.Collection.__len__` has 59 overrides, this might slow down the analysis considerably.
ƛ  `typing.GenericMeta.__getitem__` has 72 overrides, this might slow down the analysis considerably.
ƛ  `typing.Iterable.__iter__` has 57 overrides, this might slow down the analysis considerably.
ƛ  `typing.NamedTuple.__init__` has 232 overrides, this might slow down the analysis considerably.
ƛ  vuln:15:4-15:15: Revealed type for engine.execute: BoundMethod[typing.Callable(sqlalchemy.engine.base.Engine.execute)[..., unknown][[[Named(self, sqlalchemy.engine.base.Engine), Named(statement, typing.Union[sqlalchemy.sql.compiler.Compiled, sqlalchemy.sql.ddl.DDLElement, sqlalchemy.sql.elements.ClauseElement, sqlalchemy.sql.functions.FunctionElement, sqlalchemy.sql.schema.DefaultGenerator]), Variable(typing.Mapping[str, typing.Any]), Keywords(typing.Any)], sqlalchemy.engine.cursor.CursorResult][[Named(self, sqlalchemy.engine.base.Engine), Named(statement, str), Variable(typing.Any), Keywords(typing.Any)], sqlalchemy.engine.cursor.CursorResult]], sqlalchemy.engine.base.Engine]
ƛ  vuln:21:4-21:15: Revealed type for engine.execute: BoundMethod[typing.Callable(sqlalchemy.engine.base.Engine.execute)[..., unknown][[[Named(self, sqlalchemy.engine.base.Engine), Named(statement, typing.Union[sqlalchemy.sql.compiler.Compiled, sqlalchemy.sql.ddl.DDLElement, sqlalchemy.sql.elements.ClauseElement, sqlalchemy.sql.functions.FunctionElement, sqlalchemy.sql.schema.DefaultGenerator]), Variable(typing.Mapping[str, typing.Any]), Keywords(typing.Any)], sqlalchemy.engine.cursor.CursorResult][[Named(self, sqlalchemy.engine.base.Engine), Named(statement, str), Variable(typing.Any), Keywords(typing.Any)], sqlalchemy.engine.cursor.CursorResult]], sqlalchemy.engine.base.Engine]
[]
root@229a900571ee:/usr/src/app# pyre analyze
ƛ  `google.protobuf.message.Message.ClearField` has 57 overrides, this might slow down the analysis considerably.
ƛ  `google.protobuf.message.Message.__init__` has 58 overrides, this might slow down the analysis considerably.
ƛ  `libcst._nodes.base.CSTNode._codegen_impl` has 102 overrides, this might slow down the analysis considerably.
ƛ  `libcst._nodes.base.CSTNode._visit_and_replace_children` has 119 overrides, this might slow down the analysis considerably.
ƛ  `object.__eq__` has 530 overrides, this might slow down the analysis considerably.
ƛ  `object.__hash__` has 115 overrides, this might slow down the analysis considerably.
ƛ  `object.__init__` has 1927 overrides, this might slow down the analysis considerably.
ƛ  `object.__ne__` has 370 overrides, this might slow down the analysis considerably.
ƛ  `object.__repr__` has 176 overrides, this might slow down the analysis considerably.
ƛ  `object.__setattr__` has 52 overrides, this might slow down the analysis considerably.
ƛ  `object.__str__` has 81 overrides, this might slow down the analysis considerably.
ƛ  `pika.amqp_object.Method.synchronous` has 66 overrides, this might slow down the analysis considerably.
ƛ  `type.__call__` has 220 overrides, this might slow down the analysis considerably.
ƛ  `type.__init__` has 1674 overrides, this might slow down the analysis considerably.
ƛ  `type.__new__` has 294 overrides, this might slow down the analysis considerably.
ƛ  `type.__or__` has 53 overrides, this might slow down the analysis considerably.
ƛ  `typing.Collection.__len__` has 59 overrides, this might slow down the analysis considerably.
ƛ  `typing.GenericMeta.__getitem__` has 72 overrides, this might slow down the analysis considerably.
ƛ  `typing.Iterable.__iter__` has 57 overrides, this might slow down the analysis considerably.
ƛ  `typing.NamedTuple.__init__` has 232 overrides, this might slow down the analysis considerably.
[]

Additional context
I'm providing no cache flag. I don't see any state files being written so maybe this is a race condition.

[arthaud]

Hi @cyounkins, thanks for the report.
I have been looking a bit into this.

I think that's because the pyre python client calls the pyre OCaml binary, and that one writes its logs to stdout, and then they go through multiple hops in the client: ocaml binary stderr -> log file -> tail -F -> pyre client stderr (i.e your terminal). My guess is that when we get the final result from the ocaml binary, the logs do not reach the final logger before we stop logging.
This happens around: https://github.com/facebook/pyre-check/blob/main/client/commands/analyze.py#L350-L361
Adding a time.sleep(1) there seems to fix the problem, but it is obviously less than ideal.
I think we need to increase the refresh rate of tail (using option -s), but that isn't available on MacOS, only on Linux. So we might have to implement our own tail function in Python (we discussed this before).

I have a fix internally, I will need to run more tests on it and go through code review.

[cyounkins]

So you were able to reproduce it then?

The reader could wait for a sentinel string. Or you could tail it yourself in python.

[arthaud]

Yes I'm able to reproduce and I have a fix doing the tail in python. Please hold on while it goes through code review internally.