Python plugin fails intermittently to find an interpreter

[mr-cal]

What needs to get done

Fix the intermittent failure to find an interpreter in the Python plugin.

Why it needs to get done

The python plugin fails intermittently in Rockcraft's and Snapcraft's spread test suite.

@cmatsuoka made some changes to outputs in #1012. This was released in craft-parts 2.6.2.

I tested this release downstream in Snapcraft in canonical/snapcraft#5273 but the error is still intermittent for the "not provisioned" tests within the Python symlinks test suite.

[syncronize-issues-to-jira]

Thank you for reporting your feedback to us!

The internal ticket has been created: https://warthogs.atlassian.net/browse/CRAFT-4220.

This message was autogenerated

[cmatsuoka]

The error log reads:

2025-02-20T18:23:33.7694284Z :: + echo Looking for a Python interpreter called '"python3.10"' in the payload...
2025-02-20T18:23:33.7695499Z :: Looking for a Python interpreter called "python3.10" in the payload...
2025-02-20T18:23:33.7697126Z :: ++ find /root/parts/python-sample/install/usr/bin /root/stage/usr/bin -type f -executable -name python3.10 -print -quit
2025-02-20T18:23:33.7698636Z :: ++ true
2025-02-20T18:23:33.7699190Z :: + payload_python=
2025-02-20T18:23:33.7700848Z Failed to run the build script for part 'python-sample'.

Meaning that the script executon stops at the payload_python assignment, right after true is executed. The relevant lines in the script being executed are:

    set -e

    ...

    # look for python3.10
    basename=$(basename $(readlink -f ${{PARTS_PYTHON_VENV_INTERP_PATH}}))
    echo Looking for a Python interpreter called \\"${{basename}}\\" in the payload...
    payload_python=$(find "$install_dir" "$stage_dir" -type f -executable -name "${{basename}}" -print -quit 2>/dev/null || true)

    if [ -n "$payload_python" ]; then
        # We found a provisioned interpreter, use it.
        echo Found interpreter in payload: \\"${{payload_python}}\\"
        ...
    else
        # Otherwise use what _get_system_python_interpreter() told us.
        echo "Python interpreter not found in payload." >&2
        symlink_target="{python_interpreter}"
    fi

[tigarmo]

Here's another example, from Rockcraft using craft-parts 2.6.2
https://github.com/canonical/rockcraft/actions/runs/13591561730/job/37999582498

[sergiusens]

If this cannot be fixed, we probably want to look into reverting this change and going to the strategy of grabbing the error (or combined stream rather) that happens after the +

[cmatsuoka]

Adding debug messages to the bash script being executed revealed that the output processing loop is exiting too early, causing the error message to be returned before stream contents are completely collected. Refactoring it to run the output collecting loop after testing for subprocess ending solves this race.

2025-03-07T15:00:45.9351404Z :: ++ find /snapcraft/tests/spread/plugins/craft-parts/python-symlinks/classic-not-provisioned/parts/python-sample/install/usr/bin /snapcraft/tests/spread/plugins/craft-parts/python-symlinks/classic-not-provisioned/stage/usr/bin -type f -executable -name python3.10 -print -quit
2025-03-07T15:00:45.9354991Z :: find: ‘/snapcraft/tests/spread/plugins/craft-parts/python-symlinks/classic-not-provisioned/parts/python-sample/install/usr/bin’: No such file or directory
2025-03-07T15:00:45.9356947Z :: find: ‘/snapcraft/tests/spread/plugins/craft-parts/python-symlinks/classic-not-provisioned/stage/usr/bin’: No such file or directory
2025-03-07T15:00:45.9358145Z :: ++ true
2025-03-07T15:00:45.9358838Z :: + payload_python=
2025-03-07T15:00:45.9359475Z :: + echo '##### 1'
2025-03-07T15:00:45.9359903Z :: ##### 1
2025-03-07T15:00:45.9360444Z ::
2025-03-07T15:00:45.9360730Z :: ##### 2
2025-03-07T15:00:45.9361178Z :: ##### 4
2025-03-07T15:00:45.9362144Z :: ##### 5
2025-03-07T15:00:45.9362821Z Failed to run the build script for part 'python-sample'.
2025-03-07T15:00:45.9363259Z 
2025-03-07T15:00:45.9364511Z :: find: ‘/snapcraft/tests/spread/plugins/craft-parts/python-symlinks/classic-not-provisioned/parts/python-sample/install/usr/bin’: No such file or directory
2025-03-07T15:00:45.9367004Z :: find: ‘/snapcraft/tests/spread/plugins/craft-parts/python-symlinks/classic-not-provisioned/stage/usr/bin’: No such file or directory
2025-03-07T15:00:45.9368104Z :: ++ true
2025-03-07T15:00:45.9368771Z :: + payload_python=
2025-03-07T15:00:45.9369390Z :: + echo '##### 1'
2025-03-07T15:00:45.9370287Z Check the build output and verify the project can work with the 'python' plugin.

With additional tracing for output processing:

2025-03-08T14:48:06.5850615Z === fd:5   linebuf:'bytearray(b'++ true\n')'
2025-03-08T14:48:06.5851390Z === result: 8
2025-03-08T14:48:06.5851852Z === fd:5   linebuf:'bytearray(b'+ payload_python=\n')'
2025-03-08T14:48:06.5852477Z === result: 18
2025-03-08T14:48:06.5853308Z === fd:5   linebuf:'bytearray(b"+ echo \'##### 1\'\n")'
2025-03-08T14:48:06.5853882Z === result: 17
2025-03-08T14:48:06.5854324Z === fd:5   linebuf:'bytearray(b'##### 1\n')'
2025-03-08T14:48:06.5854828Z === result: 8
2025-03-08T14:48:06.5855276Z === fd:5   linebuf:'bytearray(b"+ echo \'\'\n")'
2025-03-08T14:48:06.5855831Z === result: 10
2025-03-08T14:48:06.5856776Z === fd:5   linebuf:'bytearray(b'\n')'
2025-03-08T14:48:06.5857455Z === result: 1
2025-03-08T14:48:06.5857978Z :: + echo ''
2025-03-08T14:48:06.5859106Z ::
2025-03-08T14:48:06.5859751Z :: + echo '##### 2'
2025-03-08T14:48:06.5860227Z :: ##### 2
2025-03-08T14:48:06.5860781Z :: ##### 4
2025-03-08T14:48:06.5861244Z :: ##### 5
2025-03-08T14:48:06.5947703Z Failed to run the build script for part 'python-sample'.
2025-03-08T14:48:06.5948254Z 
2025-03-08T14:48:06.5948439Z :: + echo '##### 1'
2025-03-08T14:48:06.5948792Z :: + echo ''
2025-03-08T14:48:06.5949229Z :: + echo '##### 2'
2025-03-08T14:48:06.5949967Z Check the build output and verify the project can work with the 'python' plugin.
2025-03-08T14:48:06.5951137Z Full execution log: '/root/.local/state/snapcraft/log/snapcraft-20250308-144739.019172.log'
2025-03-08T14:48:06.5951982Z === fd:5   linebuf:'bytearray(b"+ echo \'##### 2\'\n")'
2025-03-08T14:48:06.5952422Z === result: 17
2025-03-08T14:48:06.5953056Z === fd:5   linebuf:'bytearray(b'##### 2\n##### 4\n##### 5\n')'
2025-03-08T14:48:06.5954377Z === result: 24

[mr-cal]

Fixed in #1036