Log-Line "Received request of type FindReferencesRequest:" should be shown once received, not when fulfilled

[pscheit]

It feels to me that this line in the serena jetbrains panel:

Received request of type FindReferencesRequest: params={"namePath":"Port/SelectableOptionChoice","relativePath":"src/php/YAY/Shared/Application/Port/SelectableOptionChoice.php","includeQuickInfo":false}

Is only printed when the request was already completed. It prints out "Found x references" directly afterwards. However for better understanding (does it still do something), I would like to see this line earlier, so that I know "aha Serena is now working on it".

I probably see better details in the dashboard, but chose to not have this as an automatic popup (so cant open it)

[opcode81]

@pscheit, the message is actually printed immediately upon receiving the request. Finding references is indeed fast when the index is already built up.

If you are running Serena on Windows, try the GUI tool window instead of the dashboard.
Also, I just started working on alternative ways of providing access to the dashboard (particularly via the system tray); see oraios/serena#1117

[pscheit]

Ah! Found the issue. The reason why I dont see them early enough is that the first requests (without knowing the correct port number yet) are each timing out.

  Log

  INFO  08:55:19.022  jet_brains_find_symbol: name_path_pattern='IntegrationApiRateLimit', depth=1

  # Port scan starts - probing ports 24226-24245 in parallel
  DEBUG 08:55:19.023  Starting new HTTP connection (1): 192.168.16.1:24226
  DEBUG 08:55:19.024  Starting new HTTP connection (1): 192.168.16.1:24227
  DEBUG 08:55:19.025  Starting new HTTP connection (1): 192.168.16.1:24229   ← nothing listening
  DEBUG 08:55:19.026  Starting new HTTP connection (1): 192.168.16.1:24230   ← nothing listening
  DEBUG 08:55:19.027  Starting new HTTP connection (1): 192.168.16.1:24231   ← nothing listening
  ...ports 24232-24245 all tried, none listening...

  # 3 ports respond quickly:
  DEBUG 08:55:19.029  http://192.168.16.1:24226 "GET /status HTTP/1.1" 200  (webapp)
  DEBUG 08:55:19.030  http://192.168.16.1:24227 "GET /status HTTP/1.1" 200  (private-packagist)
  DEBUG 08:55:19.038  http://192.168.16.1:24228 "GET /status HTTP/1.1" 200  (private-packagist2)

  # ...then nothing for over 2 minutes while TCP connections to dead ports time out...

  DEBUG 08:57:36.250  Resetting dropped connection: 192.168.16.1
  DEBUG 08:57:36.342  http://192.168.16.1:24228 "POST /findSymbol HTTP/1.1" 200

  INFO  08:57:36.352  Task-1:JetBrainsFindSymbolTool completed in 2 minutes, 17.3 seconds

  After the first call, subsequent calls use the cached port and are fast:

  INFO  08:57:36.437  Task-2:JetBrainsFindSymbolTool completed in 0.080 seconds
  INFO  08:57:40.364  Task-3:JetBrainsFindSymbolTool completed in 0.117 seconds
  INFO  08:57:40.800  Task-4:JetBrainsFindSymbolTool completed in 0.135 seconds

JetBrainsPluginClientManager scans 20 ports (NUM_PORTS_TO_SCAN = 20) starting from BASE_PORT (24226). Each port probe uses PLUGIN_REQUEST_TIMEOUT = 300 seconds as the HTTP timeout. When running over WSL2→Windows networking, TCP connections to non-listening ports take ~8 seconds each to time out. With only 3 IDEs open, the remaining 17 ports cause ~136 seconds of wasted timeout.

The _last_port cache (in from_project) makes subsequent calls fast, but every new Serena process pays this cost on its first tool call.

[opcode81]

non-listening ports take ~8 seconds each to time out. With only 3 IDEs open, the remaining 17 ports cause ~136 seconds of wasted timeout.

This is strange though, because Serena scans the ports in parallel, so it should only be ~8 seconds. (On native Windows, it is ~1 second.)
Unless the underlying system forces the parallel requests to be synchronised, the timeouts should not be additive.

[pscheit]

I'll send you another full log when this happens again