[Bug]: custom/script receiving multiple lines rapidly only displays first line

[Isak05]

Checklist

• I have read the appropriate section in the contributing guidelines
• I believe this issue is a problem with polybar itself and not a misconfiguration on my part
• I have searched for other open and closed issues that may have already reported this problem
• I have checked the known issues page for this problem.
• I have followed the debugging guide to narrow down the problem to a minimal config.

Steps to reproduce

Just run polybar with the minimal config.

You might have to exit and rerun it a couple times to see the bug. On my main system the bug appears every time, but when I tried it on a virtual machine it sometimes correctly displayed 2, and sometimes incorrectly 1.

Minimal config

[bar/bar1]
modules-right = test

[module/test]
type = custom/script
tail = true
exec = echo -e "1\\n2" && sleep infinity

Polybar log

notice: Parsing config file: /home/user/.config/polybar/config.ini
- config_parser: Parsing /home/user/.config/polybar/config.ini
* Loaded monitor eDP-1 (1920x1080+0+0)
* Configured DPI = 96x96
* Bar geometry: 1920x24+0+0; Borders: 0,0,0,0
- bar: Attach X event sink
- bar: Attach signal receiver
- controller: Setup user-defined modules
notice: Loading module 'test' of type 'custom/script'
notice: Loaded 1 modules
* Starting application
- controller: Main thread id = 1
* Entering event loop (thread-id=1)
- bar: Create renderer
- renderer: Get TrueColor visual
* renderer: Using 32-bit TrueColor visual: 0x283
- renderer: Allocate colormap
- renderer: Allocate output window
- renderer: Allocate window pixmaps
- renderer: Allocate graphic contexts
- renderer: Allocate alignment blocks
- renderer: Allocate cairo components
- renderer: Load fonts
warn: No fonts specified, using fallback font "fixed"
notice: Loaded font "fixed" (name=Noto Sans, offset=0, file=/usr/share/fonts/noto/NotoSans-Regular.ttf)
* Bar window: 0x4a00001
- bar: Reconfigure window
- bar: Set window WM_NAME
- bar: Set window _NET_WM_WINDOW_TYPE
- bar: Set window _NET_WM_STATE
- bar: Set window _NET_WM_DESKTOP
- bar: Set window _NET_WM_PID
- bar: Map window
- background_manager: update_geometry
- background_manager: deactivating because there are no slices to observe
- bar: Draw empty bar
- bar: Setup tray manager
* Starting module/test
* script_runner: Invoking shell command: "echo -e "1\n2" && sleep infinity"
* module/test: Rebuilding cache
- bar: Force update
* Redrawing bar window
- bar: Received expose event
- background_manager: update_geometry
- background_manager: deactivating because there are no slices to observe
- background_manager: update_geometry
- background_manager: deactivating because there are no slices to observe
* module/test: Rebuilding cache
* Redrawing bar window
- renderer: flush(3 geom=9x24+1911+0, falloff=0)

Expected behavior

When receiving two lines at the same time or in rapid succession I expect the module to display the last received one. In this case it should display 2.

Actual behavior

The module only displays the first received line. In this case 1.

Window Manager and Version

i3 4.23-3

Linux Distribution

Arch

Polybar version

polybar 3.7.1

Features: +alsa +curl +i3 +mpd +network(libnl) +pulseaudio +xkeyboard

X extensions: +randr (+monitors) +composite +xkb +xrm +xcursor

Build type: Release
Compiler: /usr/bin/c++
Compiler flags: -march=x86-64 -mtune=generic -O2 -pipe -fno-plt -fexceptions         -Wp,-D_FORTIFY_SOURCE=2 -Wformat -Werror=format-security         -fstack-clash-protection -fcf-protection -Wp,-D_GLIBCXX_ASSERTIONS -g -ffile-prefix-map=/build/polybar/src=/usr/src/debug/polybar -flto=auto -O3 -DNDEBUG -Wall -Wextra -Wpedantic -Wdeprecated-copy-dtor -Wsuggest-override
Linker flags: -Wl,-O1,--sort-common,--as-needed,-z,relro,-z,now -flto=auto -Wall -Wextra -Wpedantic -Wdeprecated-copy-dtor -Wsuggest-override  -Wall -Wextra -Wpedantic -Wdeprecated-copy-dtor -Wsuggest-override

Additional Context / Screenshots

The bug is present when building from source as well.

The bug comes from the following code in src/adapters/script_runner.cpp

  while (!m_stopping && cmd.is_running() && !io_util::poll(fd, POLLHUP, 0)) {
    if (io_util::poll_read(fd, 250)) {
      auto changed = set_output(cmd.readline());

      if (changed) {
        m_on_update(m_data);
      }
    }
  }

What I believe is happening is that io_util::poll_read(fd, 250) will poll the stdout file descriptor of the script. If there is data in the file descriptor cmd.readline() will read the first line and the second line will get automatically buffered by the underlying stream. When io_util::poll_read(fd, 250) runs again, the file descriptor will be empty since the data has already been read into the m_stdout_reader stream buffer. Therefore the second line never gets displayed.

One solution is to create a function in src/utils/command.cpp that will first check the stream buffer and then poll the file descriptor.

 bool command<output_policy::REDIRECTED>::wait_for_data(int timeout_ms) {
   return (m_stdout_reader && m_stdout_reader->rdbuf()->in_avail() > 0) ||
           io_util::poll_read(get_stdout(PIPE_READ), timeout_ms);
 }

Then call cmd.wait_for_data(250) instead of io_util::poll_read(fd, 250).

This partially resolves the bug. There still appears to be a small chance that the bug will occur. This is because sometimes polybar will rebuild the cache immediately after receiving the first line, and while doing so it will receive the second line.
Relevant code in include/modules/meta/base.inl:

    if (m_changed) {
      m_log.info("%s: Rebuilding cache", name());
      m_cache = CAST_MOD(Impl)->get_output();
      // Make sure builder is really empty
      m_builder->flush();
      if (!m_cache.empty()) {
        // Add a reset tag after the module
        m_builder->control(tags::controltag::R);
        m_cache += m_builder->flush();
      }
      m_changed = false;
    }

One possible solution is to move the m_changed = false; to the beginning of the if statement, so that it can get set back to true even when it's already building the cache. Or maybe a mutex lock could be used instead.

[patrick96]

Thanks a lot for getting to the bottom of this. Your entire analysis is spot-on.

Totally agree that we need the wait_for_data function. As for m_changed, I would suggest replacing the if header with if (m_changed.exchange(false)) {. This way, we atomically set it to false and never lose an update to m_changed.

Do you want to open a PR with the fix? Ideally, branch off the 3.7.1 tag and target the hotfix/3.7.2 branch when opening the PR, so that we can get it into the next bugfix release.

[Isak05]

Great! I will open a PR with the changes.