[Bug]: Logs not loading from first time

[okt-limonikas]

App Version

All versions

Browser

Chrome/Firefox

Bug Description

When a test log JSON file has not been generated yet, opening that test can
show an empty or unavailable log panel. Selecting another test and then
returning to the original test makes the log appear.

The failure is intermittent and is more likely for large, uncached logs or when
multiple requests reach the same generated JSON URL concurrently.

The first request can receive an empty, truncated, or malformed JSON document.
The UI remains in an error state until navigation causes another request.

Steps to Reproduce

1. Open a run log.
2. Select a test in the tree.
3. The selected test metadata may load, but its log is empty or unavailable.
4. Select another test; its log loads normally.
5. Return to the original test; its log now loads normally.

Affected components

• bublik-ui/apps/bublik and its Bublik API service library;
• the Django Bublik API;
• the Test Environment log server CGI handler;
• rgt-xml2json on-demand JSON generation;
• nginx/Apache routing for /logs/ resources.

Request flow and component relationship

Loading a selected test log is a two-stage request:

1. React requests /api/v2/logs/<focus-id>/json/ from Django.
2. Django returns metadata containing a /logs/.../json/node_idN.json URL.
3. React fetches that URL separately through nginx.
4. nginx proxies /logs/ to the Apache Test Environment log server.
5. If the JSON file is missing, Apache invokes the 404 CGI handler.
6. The CGI handler runs rgt-log-get-item, which invokes rgt-xml2json.

Django does not generate or stream the JSON document. It supplies the URL, and
the React application consumes the document directly from the log server.

Why it happens

rgt-xml2json opens the final public filename directly with
fopen(..., "w").

The filename therefore became visible to Apache as soon as generation started.
Another request could see that the file existed and receive it as a static file
while the converter was still writing it. Concurrent CGI executions could also
truncate and write the same public file simultaneously.

Depending on timing, clients received:

• a zero-byte response;
• a valid JSON prefix ending in the middle of a string or object;
• a full-sized but malformed document produced by concurrent writers;
• a prematurely closed HTTP transfer.

React previously attempted response.json() once. A parsing error left the log
query in its error state. By the time the user selected another test and
returned, generation had usually completed, so the next request succeeded.

Why only some logs are affected

• Already-generated JSON files do not enter the generation path.
• Small files may finish before a second request can read the public path.
• Large files expose the partial-write window for longer.
• More concurrent requests increase the probability of reading or writing the
  file during that window.
• Local development data often already contains generated JSON, hiding the
  problem.

Production evidence

https://ts-factory.io/bublik/v2/log/6749219?focusId=6749295&mode=treeAndinfoAndlog

The supplied focus ID, 6749295, rendered successfully during verification
because its generated JSON was already cached.

An initially uncached test from the same run reproduced the issue:

focusId: 6750527
Django metadata:
https://ts-factory.io/bublik/api/v2/logs/6750527/json/

Generated JSON URL:
https://ts-factory.io/logs/dpdk-ethdev-ts/2026/08/03/virtio_virtio:dain-cbs-speed-stack-00:27:38/json/node_id1308.json

Twenty-four concurrent requests produced:

• multiple curl: (52) Empty reply from server failures;
• multiple curl: (18) transfer closed with ... bytes remaining failures;
• six saved response bodies between 0 and 495,616 bytes;
• zero valid saved JSON responses.

A later single request to the same URL returned:

HTTP status: 200
Downloaded: 725008 bytes
JSON validation: valid object containing root

This confirms that the resource becomes usable after generation finishes.

The node_id1308.json production resource is now cached as a result of the
verification. It will not reproduce the first-generation race again unless the
generated file is removed by an authorized operator. Use another uncached test
for any further public check.

Reproducing with another uncached production log

Only run concurrent production checks when authorized. They are read requests,
but they intentionally trigger on-demand generation and increase server load.

First obtain the generated URL for a candidate focus ID without fetching the
generated document:

focus_id=6750527
curl -sS "https://ts-factory.io/bublik/api/v2/logs/$focus_id/json/" | jq .

For an uncached candidate, request its returned url concurrently:

url='https://ts-factory.io/logs/<run-directory>/json/node_idN.json'
output_dir=/tmp/bublik-public-log-race
mkdir -p "$output_dir"

for i in {1..16}; do
  curl -sSL "$url" -o "$output_dir/response-$i.json" &
done
wait

valid=0
invalid=0
for file in "$output_dir"/response-*.json; do
  if jq -e 'type == "object" and has("root")' "$file" >/dev/null 2>&1; then
    valid=$((valid + 1))
  else
    echo "invalid: $file ($(wc -c < "$file") bytes)"
    invalid=$((invalid + 1))
  fi
done

echo "summary: $valid valid, $invalid invalid"

The race is reproduced if any request is empty, terminates early, or fails the
jq validation. A later single request will usually be valid because generation
has completed by then.

Local reproduction

Use the main bublik-ui and test-environment branch revisions, then build and
start the production deployment from bublik-docker:

git -C bublik-ui switch main
git -C test-environment switch main
task build
task up

Wait until the log-server container reports Starting Apache:

docker compose logs te-log-server | tail -50

Delete the generated JSON file. The source bundle remains intact, so the next
request regenerates it:

rm -f data/logs/logs/example_log/json/node_id33.json

Run the concurrent request check:

url='http://127.0.0.1:42000/logs/example_log/json/node_id33.json'
output_dir=/tmp/bublik-local-log-race
mkdir -p "$output_dir"

for i in {0..16}; do
  curl -sSL "$url" -o "$output_dir/response-$i.json" &
done
wait

valid=0
invalid=0
for file in "$output_dir"/response-*.json; do
  if jq -e 'type == "object" and has("root")' "$file" >/dev/null 2>&1; then
    valid=$((valid + 1))
  else
    echo "invalid: $file ($(wc -c < "$file") bytes)"
    invalid=$((invalid + 1))
  fi
done

echo "summary: $valid valid, $invalid invalid"

Verified pre-fix result:

summary: 10 valid, 7 invalid

Some invalid responses had the expected 1,877,181-byte final size, confirming
that concurrent writes can corrupt the contents without making the file appear
short.

Reproducing the UI symptom locally

After deleting node_id33.json, open:

http://127.0.0.1:42000/v2/log/65360?mode=treeAndlog&focusId=65393

To make the timing window easier to hit, run the concurrent request command
while loading or reloading that page.

If the first log request receives malformed JSON, the log panel is empty or
unavailable. Select another test_one test in the tree and then return to
focus ID 65393. The original log should now appear because the generated file
has finished writing.