pw_transfer: Integration tests failing on macOS [294101325]

Fixed

Bug

Status Update

No update yet.

Description

am...@google.com

created issue #1

Aug 1, 2023 08:06PM

Several pw_transfer tests are failing on the macOS Bazel build:

//pw_transfer/integration_test:cross_language_medium_read_test
//pw_transfer/integration_test:cross_language_small_test
//pw_transfer/integration_test:expected_errors_test
//pw_transfer/integration_test:legacy_binaries_test
//pw_transfer/integration_test:multi_transfer_test

Log snippet from a failure:

...
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=89312, window_end_offset=89792, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 5993 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=89716, window_end_offset=90196, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 6004 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=89994, window_end_offset=90474, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 6019 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=90398, window_end_offset=90878, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 6035 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=90802, window_end_offset=91282, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 6051 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=91206, window_end_offset=91686, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 6066 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=91610, window_end_offset=92090, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 6081 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=92014, window_end_offset=92494, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 6095 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=92418, window_end_offset=92898, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 6102 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=92696, window_end_offset=93176, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 6117 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=93100, window_end_offset=93580, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 6133 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=93504, window_end_offset=93984, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 6148 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=93908, window_end_offset=94388, max_chunk_size=449
CLIENT OUT: DBG  Receive transfer 1 timed out waiting for chunk; resending parameters
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=93984, window_end_offset=94388, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 5442 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=94186, window_end_offset=94666, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 5455 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=94590, window_end_offset=95070, max_chunk_size=449
CLIENT OUT: DBG  Transfer 1 expected offset 94666, received 94868; entering recovery state
CLIENT OUT: INF  Transfer rate: 5450 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=94666, window_end_offset=95146, max_chunk_size=449
CLIENT OUT: DBG  Transfer 1 received expected offset 94666, resuming transfer
CLIENT OUT: INF  Transfer rate: 5464 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=95070, window_end_offset=95550, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 5479 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=95474, window_end_offset=95954, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 5494 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=95878, window_end_offset=96358, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 5508 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=96282, window_end_offset=96762, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 5522 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=96686, window_end_offset=97166, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 5537 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=97090, window_end_offset=97570, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 5551 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=97494, window_end_offset=97974, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 5561 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=97772, window_end_offset=98252, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 5575 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=98176, window_end_offset=98656, max_chunk_size=449
CLIENT OUT: INF  Transfer rate: 5590 B/s
CLIENT OUT: DBG  Transfer 1 sending transfer parameters: offset=98580, window_end_offset=99060, max_chunk_size=449
CLIENT OUT: INF  Transfer 1 terminating with status 0
CLIENT OUT: DBG  Sending final chunk for transfer 1 with status 0
SERVER ERR: INF  Transfer 1 completed with status 0
SERVER ERR: ERR  Failed to write chunk for transfer 1: 2
SERVER ERR: INF  Transfer 1 terminating with status 13
SERVER ERR: DBG  Sending final chunk for transfer 1 with status 13
SERVER ERR: ERR  Failed to write chunk for transfer 1: 2
PROXY  ERR: 19:38:39.274-INFO: client connection closed.
SERVER OUT: INF  Server loaded config:
SERVER OUT: resources {
SERVER OUT:   key: 5
SERVER OUT:   value {
SERVER OUT:     source_paths: "/var/folders/l6/677rkrv13fg452nf3vcz_fmc00jw6r/T/tmph9jcnr8
F
======================================================================
FAIL: test_large_hdlc_escape_client_read_1_cpp (__main__.MediumTransferReadIntegrationTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/private/var/tmp/_bazel_amontanez/e724b21efc8bc19866072fbc72ee5907/execroot/pigweed/bazel-out/darwin-fastbuild/bin/pw_transfer/integration_test/cross_language_medium_read_test.runfiles/python_packages_parameterized/site-packages/parameterized/parameterized.py", line 533, in standalone_func
    return func(*(a + p.args), **p.kwargs)
  File "/private/var/tmp/_bazel_amontanez/e724b21efc8bc19866072fbc72ee5907/execroot/pigweed/bazel-out/darwin-fastbuild/bin/pw_transfer/integration_test/cross_language_medium_read_test.runfiles/pigweed/pw_transfer/integration_test/cross_language_medium_read_test.py", line 79, in test_large_hdlc_escape_client_read
    self.do_single_read(
  File "/Users/amontanez/development/projects/pigweed/pigweed/pw_transfer/integration_test/test_fixture.py", line 489, in do_single_read
    self.assertEqual(exit_codes.client, 0)
AssertionError: -6 != 0

----------------------------------------------------------------------
Ran 1 test in 18.304s

FAILED (failures=1)

The two status codes are PW_STATUS_UNKNOWN and PW_STATUS_INTERNAL.

Comments

bl...@google.com <bl...@google.com> #2Aug 1, 2023 08:22PM

Assigned to he...@google.com.

Automated by Blunderbuss job pigweed-blunderbuss-autoassigner for component 1194524.

am...@google.com <am...@google.com> #3Aug 1, 2023 08:53PM

Initial investigation:

legacy_binaries_test is a red herring; it's only compatible with macOS.
The failing tests are flaky; if you run them many times they'll occasionally pass.
The failures only seem to occur on the C++ client, which suggests this might be related to how the test fixture tears down the C++ client.

ap...@google.com <ap...@google.com> #4Aug 2, 2023 12:06AM

Project: pigweed/pigweed
Branch: main

commit 9231b05b13226c94f36e43c9497a0c642d8bb66d
Author: Armando Montanez <amontanez@google.com>
Date: Wed Aug 02 00:05:33 2023

pw_transfer: Mark linux-only Bazel tests

Marks the legacy_binaries_test integration as linux-only as legacy
binaries are only provided for linux-x86_64.

Bug:

b/294101325

Change-Id: If4aa6363b6cf26c3dfc2b22b78c33de01b9b83d9
Reviewed-on:

https://pigweed-review.googlesource.com/c/pigweed/pigweed/+/162094
Pigweed-Auto-Submit: Armando Montanez <amontanez@google.com>
Commit-Queue: Auto-Submit <auto-submit@pigweed-service-accounts.iam.gserviceaccount.com>
Presubmit-Verified: CQ Bot Account <pigweed-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Carlos Chinchilla <cachinchilla@google.com>

M pw_transfer/integration_test/BUILD.bazel

https://pigweed-review.git.corp.google.com/162094

am...@google.com <am...@google.com> #5Aug 3, 2023 11:12PM

Reassigned to am...@google.com.

Yup, it's a teardown ordering issue:

PROXY  ERR: 22:58:36.752-INFO: New client connection from ('::1', 51930, 0, 0)
SERVER ERR: INF  Starting pw_rpc server
PROXY  ERR: 22:58:36.763-INFO: New connection opened to server
PROXY  ERR: 22:58:36.763-INFO: client DataDropper initialized with seed 1649963713563718435
PROXY  ERR: 22:58:36.763-INFO: server DataDropper initialized with seed 1649963713563718436
SERVER ERR: INF  Starting read transfer 1 for resource 5
SERVER ERR: DBG  Local transfer timing configuration: chunk_timeout=5000ms, max_retries=4, interchunk_delay=2000us
SERVER ERR: DBG  Local transfer windowing configuration: pending_bytes=32768, extend_window_divisor=32, max_chunk_size_bytes=216
SERVER ERR: DBG  Preparing read for file /var/folders/l6/677rkrv13fg452nf3vcz_fmc00jw6r/T/tmpcyl3883m
SERVER ERR: DBG  Negotiating protocol version: ours=2, theirs=2
SERVER ERR: INF  Transfer 1: using protocol version 2
SERVER ERR: DBG  Transfer 1 received parameters type=RETRANSMIT offset=0 window_end_offset=480
SERVER ERR: DBG  Transfer 1 sending chunk offset=0 size=206
SERVER ERR: DBG  Transfer 1 sending chunk offset=206 size=203
SERVER ERR: DBG  Transfer 1 received parameters type=CONTINUE offset=409 window_end_offset=889
SERVER ERR: DBG  Transfer 1 sending chunk offset=409 size=103
SERVER ERR: DBG  Transfer 1 sending final chunk with remaining_bytes=0
CLIENT ERR: libc++abi: terminating due to uncaught exception of type std::__2::system_error: mutex lock failed: Invalid argument
CLIENT OUT: INF  Client loaded config:
CLIENT OUT: transfer_actions {
CLIENT OUT:   resource_id: 5
CLIENT OUT:   file_path: "/var/folders/l6/677rkrv13fg452nf3vcz_fmc00jw6r/T/tmp9pqhmgh
CLIENT OUT: INF  Connecting to pw_rpc client at localhost:3305
CLIENT OUT: INF  Starting transfer for resource 5
CLIENT OUT: DBG  Negotiating protocol version: ours=2, theirs=2
CLIENT OUT: INF  Transfer 1: using protocol version 2
CLIENT OUT: INF  Transfer rate: 9511 B/s

Key line:

CLIENT ERR: libc++abi: terminating due to uncaught exception of type std::__2::system_error: mutex lock failed: Invalid argument

The mutex is likely getting destroyed before another thread attempts to use it.

ap...@google.com <ap...@google.com> #6Aug 8, 2023 11:42PM

Project: pigweed/pigweed
Branch: main

commit 9361d8abd4dab7022c46a609499a8fba4016635f
Author: Armando Montanez <amontanez@google.com>
Date: Tue Aug 08 23:41:14 2023

pw_transfer: Fix use-after-destroy in integration test client

If you give a mouse a cookie, it might choose to hold onto it longer
than you expected. Except in this case, the mouse is the
pw::transfer::Client and the cookie is a BinarySemaphore.

Bug:

b/294101325

Change-Id: Ic209887ce6ed609819d42b5f06c32e5f3c030887
Reviewed-on:

https://pigweed-review.googlesource.com/c/pigweed/pigweed/+/163252
Reviewed-by: Keir Mierle <keir@google.com>
Presubmit-Verified: CQ Bot Account <pigweed-scoped@luci-project-accounts.iam.gserviceaccount.com>
Commit-Queue: Auto-Submit <auto-submit@pigweed-service-accounts.iam.gserviceaccount.com>
Pigweed-Auto-Submit: Armando Montanez <amontanez@google.com>

M pw_transfer/integration_test/client.cc

https://pigweed-review.git.corp.google.com/163252

am...@google.com <am...@google.com> Aug 9, 2023 04:14PM

Marked as fixed.

Issue 294101325