Partial job report

Question

Partial job report

alexandreSalconiDenis opened this issue 4 years ago · 29 comments

alexandreSalconiDenis commented 4 years ago

Describe the bug
When you use g:cmake_build_executor= job it seems to report only a section of the build result.
The bug was reproduce on linux, with ninja generator.

To Reproduce
I made a branch to reproduce the issue with test proj
https://github.com/alexandreSalconiDenis/cmake4vim/tree/bugfix/partialJobReport

go intotest/"test proj"
open vim
set this parameter:

let g:cmake_build_type = 'Debug'
let g:cmake_project_generator = 'Ninja'
let g:cmake_build_dir_prefix = 'build/'
let g:cmake_compile_commands_link = '.'

do :CMake
do :CMakeBuild

Expected behavior
Get error in copen for:

app/main.cpp:L6
test/src/test_class.cpp:L9

Screenshots

Desktop (please complete the following information):

OS: [Linux manjaro 20.2]
Editor [vim]
Version [8.2]

Answer 1 · 2020-12-27T19:51:48.000Z

Hi @alexandreSalconiDenis,

I tried to reproduce the issue, but cannot do that.
Maybe I forgot something? Could you recheck?
First of all I tried to reproduce it:

And after that I compared results with Dispatch:

As you can see, I got the same result. Could you recheck? Maybe I forgot something?
I used the latest master and Ubuntu 18.04.

Answer 2 · 2020-12-27T21:41:49.000Z

I managed to recreate it on arch linux 5.9.14-arch1-1, but only with executor set to 'job', 'dispatch' works fine.

Also it's a bit finicky, it doesn't always stop on the same line, sometimes it shows the exact line that has the error, other times it stops with In file included from /tmp/cmake4vim/blahblahblah.

I'll try using as clean vimrc as possible to see if that maybe affects it.

Answer 3 · 2020-12-27T22:08:02.000Z

I managed to narrow it down to the plugin vim-airline, it uses job for updating the statusline so that may have something to do with it.

I tried to recreate it in an arch linux docker and it started happenning only after installing that plugin, this is my entire .vimrc:

set nocompatible
filetype off
                        
set rtp+=~/.vim/bundle/Vundle.vim
                      
call vundle#begin()
Plugin 'VundleVim/Vundle.vim' 
Plugin 'ilyachur/cmake4vim'
Plugin 'vim-airline/vim-airline'
   
call vundle#end()
filetype plugin indent on

@alexandreSalconiDenis from the look of it, you're using it too?

Answer 4 · 2020-12-28T06:42:58.000Z

Ok,I will try to create a PR with potential fix.

Answer 5 · 2020-12-28T12:09:22.000Z

@mark2185 @alexandreSalconiDenis I created PR #72 which should fix the issue. Could you validate it?

Answer 6 · 2020-12-28T12:21:03.000Z

@ilyachur Tried it, but the result is same. The output is fixed when vim-airline is removed.

Answer 7 · 2020-12-28T12:26:19.000Z

@mark2185 ok, thank you. I thought that you get this issue due to jobs collision (if cmake4vim and someone else create jobs).

Answer 8 · 2020-12-28T12:35:17.000Z

@ilyachur Tried it, but the result is same. The output is fixed when vim-airline is removed.

Ok, maybe I will try to install vim-airline

Answer 9 · 2020-12-28T13:44:57.000Z

@ilyachur I try without vim-airline and get same issue as @mark2185. And If i do CMake it do the command and open the CMakelist.txt not sure if it's intended.

Answer 10 · 2020-12-28T13:56:52.000Z

And with vim-airline/vim-airline It's not different for me.

Answer 11 · 2020-12-28T16:28:54.000Z

I am not sure why you have such issues with partial job report. I have installed the vim-airline/vim-airline but I still cannot reproduce the issue.
Moreover thank you @mark2185 I have tried to reproduce this issue with using your .vimrc:

set nocompatible
filetype off
                        
set rtp+=~/.vim/bundle/Vundle.vim
                      
call vundle#begin()
Plugin 'VundleVim/Vundle.vim' 
Plugin 'ilyachur/cmake4vim'
Plugin 'vim-airline/vim-airline'
   
call vundle#end()
filetype plugin indent on

I tried to reproduce the issue on macOS and Ubuntu, unfortunately I don't have arch linux, maybe I will try to use docker container or install it on virtual machine.
But at the current moment I cannot reproduce it and don't have any ideas why it is happened.
I had only an idea that it could be caused by some collisions between jobs from different plugins.

Answer 12 · 2020-12-28T17:04:16.000Z

To make it easier for you, here's the entire Dockerfile:

FROM archlinux/base:latest

RUN pacman -Sy git vim cmake ninja gcc --noconfirm

RUN git clone https://github.com/VundleVim/Vundle.vim.git ~/.vim/bundle/Vundle.vim

COPY minimal_vimrc /root/.vimrc

RUN vim +PluginInstall +qall

RUN git clone https://github.com/alexandreSalconiDenis/cmake4vim.git

Also I had to remove the EXCLUDE_FROM_ALL from incorrect_lib/CMakeLists.txt:5 to get any errors.

Let me know if I can help any other way.

Answer 13 · 2020-12-28T17:18:27.000Z

@mark2185 you I think you missed the branch on the repo I changed did you test the issue on master, the branch I made to test is bugfix/partialJobReport?
my suggestion would be to change the last line to look like that:

FROM archlinux/base:latest

RUN pacman -Sy git vim cmake ninja gcc --noconfirm

RUN git clone https://github.com/VundleVim/Vundle.vim.git ~/.vim/bundle/Vundle.vim

COPY minimal_vimrc /root/.vimrc

RUN vim +PluginInstall +qall

RUN git clone https://github.com/alexandreSalconiDenis/cmake4vim.git -b bugfix/partialJobReport

WORKDIR 'cmake4vim/test/test proj'

Answer 14 · 2020-12-28T18:50:47.000Z

hi guys,

Thank you for the reproducer. I reproduced this issue in the docker. But still don't understand what happens, I see that job output callback isn't called for each line (I mean if I print each message which I get inside the output callback, the result is the same with quickfix list).
In other hand if I use another executor, the output is correct. I don't have any ideas why it is happened, need to investigate.

Answer 15 · 2020-12-28T23:28:47.000Z

Could it be that ninja perhaps doesn't flush the buffer immediately so not all messages get intercepted?

Or maybe there's a verbose mode that synchronizes the output somehow?

Answer 16 · 2020-12-30T18:30:20.000Z

I didn't use the Ninja, it means that issue isn't related with Ninja

When I tried to reproduce the issue I understood that I skip nothing, I use all messages which I get in the output callback.
At the current moment I don't know how enable more detailed debug mode.

Answer 17 · 2021-04-01T07:01:48.000Z

@ilyachur Have you had any luck with it?

I tried debugging it, thought it was because of errorformat, but it's not.

It seems to be that the s:cmake4vim_job is stopped too early and s:appendLine() isn't called anymore after that.
But the s:vimOut() still receives the rest of the output, it just doesn't pass it through.
If I put an early return in s:vimExit, it all works as expected.
If I replace the exit_cb with close_cb, it also works. It may be a bug in vim itself.

I know it's not a solution, but it's a step in the right direction, something like this:

diff --git a/autoload/utils/exec/job.vim b/autoload/utils/exec/job.vim
index 4664335..3086729 100644
--- a/autoload/utils/exec/job.vim
+++ b/autoload/utils/exec/job.vim
@@ -73,13 +73,18 @@ function! s:vimExit(channel, message) abort
     if empty(s:cmake4vim_job) || a:channel != s:cmake4vim_job['job']
         return
     endif
-    let s:cmake4vim_job = {}
     call s:createQuickFix()
     if a:message != 0
         copen
     endif
 endfunction

+function! s:vimClose(channel) abort
+    if a:channel == s:cmake4vim_job['channel']
+        let s:cmake4vim_job = {}
+    endif
+endfunction
+
 function! s:nVimOut(job_id, data, event) abort
     if empty(s:cmake4vim_job) || a:job_id != s:cmake4vim_job['job']
         return
@@ -153,6 +158,7 @@ function! utils#exec#job#run(cmd, err_fmt) abort
                     \ 'out_cb': function('s:vimOut'),
                     \ 'err_cb': function('s:vimOut'),
                     \ 'exit_cb': function('s:vimExit'),
+                    \ 'close_cb': function('s:vimClose'),
                     \ })
         let s:cmake4vim_job = {
                     \ 'job': l:job,

Let me know what you think!

This trashes the buffer if you switch to the qf window while it's writing into it (I think that part of code should be rethinked, the writing to the hidden buffer), and it cannot start another job after the first one (bug somewhere, haven't had the time to investigate).

Answer 18 · 2021-04-07T04:06:44.000Z

@mark2185 I didn't investigate this issue. It looks strange that it is reproduced only in the docker on specific vim version 😄

Am I right that it won't work if I switch windows to qf? or I didn't understand you.

Answer 19 · 2021-04-07T07:27:22.000Z

@ilyachur it isn't only in docker, it happened to me on archlinux and macOS as well.

The main problem is that s:vimExit is called before all of the output is actually processed.
That's the biggest problem, it's a race condition of some sort, I guess.

Am I right that it won't work if I switch windows to qf? or I didn't understand you.

Correct. Current master throws a bunch of E21: Cannot make changes, 'modifiable' is off. if you switch to the qf while it's building.
Maybe it would be better to use caddexpr to append directly to the qf, Dispatch works okay, I'll look into how it fills the qf.

Although, if caddexpr is used, I'm not sure errorformat is applied to the input...

Answer 20 · 2021-04-09T15:47:02.000Z

@mark2185 Thank you for explanation. I didn't faced with this issue on my mac. Maybe it can depend on vim version...

Answer 21 · 2021-04-09T17:57:04.000Z

Correct. Current master throws a bunch of E21: Cannot make changes, 'modifiable' is off. if you switch to the qf while it's building.

@mark2185 Could you please show the stacktrace or reproducer? I tried to reproduce the issue on my mac, but with your changes all works as expected.
I attached the patch with changes (honestly it is your proposal with small change):
0001-Fix-job-executor.txt

Answer 22 · 2021-04-11T07:42:29.000Z

@ilyachur here's a video. It's on the yuzu emulator (it was a random choice).

I start :CMake and then switch to the qf. I haven't tried the patch yet.

Answer 23 · 2021-04-11T09:59:41.000Z

Tried the patch, but it still doesn't output the entire job report. I will try to look into it deeper this week.

Answer 24 · 2021-04-11T15:47:17.000Z

Hi @mark2185, thank you for the video, the problem is with temporary buffer.
I created a PR: #87
Could you verify that it solves all your issues?

Answer 25 · 2021-04-11T18:28:34.000Z

PR #87 was merged, it should solve E21: Cannot make changes, 'modifiable' is off. error message.

But I am not sure that it solve the original issue.
As I understand the 'close_cb' is not a solution, because this callback is called only if you manually close the temporary buffer, at least the proposed changes are broke some tests.

Answer 26 · 2021-04-17T12:43:18.000Z

But I am not sure that it solve the original issue.
As I understand the 'close_cb' is not a solution, because this callback is called only if you manually close the temporary buffer, at least the proposed changes are broke some tests.

The close_cb is called when the channel is closed, from the :help job-close_cb:

							*close_cb*
"close_cb"	A function that is called when the channel gets closed, other
		than by calling ch_close().  It should be defined like this: 
	   func MyCloseHandler(channel)
		Vim will invoke callbacks that handle data before invoking
		close_cb, thus when this function is called no more data will
		be passed to the callbacks.  However, if a callback causes Vim
		to check for messages, the close_cb may be invoked while still
		in the callback.  The plugin must handle this somehow, it can
		be useful to know that no more data is coming.

Important bits: when this function is called no more data will be passed to the callbacks.

So, it's important to reset the s:cmake4vim_job in the close_cb, not exit_cb.

Here's the patch that processes all messages.

diff --git a/autoload/utils/exec/job.vim b/autoload/utils/exec/job.vim
index 4664335..a317b2c 100644
--- a/autoload/utils/exec/job.vim
+++ b/autoload/utils/exec/job.vim
@@ -80,6 +80,11 @@ function! s:vimExit(channel, message) abort
     endif
 endfunction
 
+function! s:vimClose(channel) abort
+    let s:cmake4vim_job = {}
+    call s:createQuickFix()
+endfunction
+
 function! s:nVimOut(job_id, data, event) abort
     if empty(s:cmake4vim_job) || a:job_id != s:cmake4vim_job['job']
         return
@@ -152,7 +157,8 @@ function! utils#exec#job#run(cmd, err_fmt) abort
         let l:job = job_start(a:cmd, {
                     \ 'out_cb': function('s:vimOut'),
                     \ 'err_cb': function('s:vimOut'),
-                    \ 'exit_cb': function('s:vimExit'),
+                    \ 'close_cb': function('s:vimClose')
                     \ })
         let s:cmake4vim_job = {
                     \ 'job': l:job,

But they're not necessarily in the right order... I get something like this:

|| -- Configuring done
|| -- Generating done
|| -- Build files have been written to: /Users/mark/workspace/build/core-utils/clang/debug
|| WARN: OpenCV/4.5.1.4@package/stable: requirement CMakeBuild/13.1.5@package/stable overridden by CoreUtils/5.4.2 to CMakeBuild/13.2.1@package/stable 
|| WARN: libjpeg-turbo/2.0.6.1@package/stable: requirement CMakeBuild/13.0.1@package/stable overridden by OpenCV/4.5.1.4@package/stable to CMakeBuild/13.2.1@package/stable

But setting the channel mode to nl seems to fix that too.

                     \ 'err_cb': function('s:vimOut'),
-                    \ 'exit_cb': function('s:vimExit'),
+                    \ 'close_cb': function('s:vimClose'),
+                    \ 'mode': 'nl',

There are some tests failing, but at least this processes all of the output.
Try it out and let me know what you think, @ilyachur !

Answer 27 · 2021-04-19T04:31:23.000Z

@mark2185,

As I understood:
"nl" - Use messages that end in a NL character

And maybe in this case I understood why in some moments you don't get some information in outputs.
Because vim also can use buffered output stream and in this case some messages are only put to the buffer without printing to the screen.

Do you know why tests start to fail? it can be correlated with expected output format

Answer 28 · 2021-04-19T07:37:02.000Z

As I understood:
"nl" - Use messages that end in a NL character

~~Yes, that may or may not have any effect in this particular situation, I'm not sure.~~
After further testing, this changes nothing. Messages are still sometimes out of order.

And maybe in this case I understood why in some moments you don't get some information in outputs.
Because vim also can use buffered output stream and in this case some messages are only put to the buffer without printing to the screen.

I don't think so.
The problem is that the job exits and cmake4vim calls s:vimExit, resetting the s:cmake4vim_job.
There are still some messages buffered, and they are passed to s:vimOut, but there is an if that checks if s:cmake4vim_job is empty (it is now since you reset it in s:vimExit) and the messages are dropped.

You can try running the docker and putting an echom in that if and you'll see there are messages received, but not printed.

That's why the s:cmake4vim_job needs to be reset in close_cb, because (from the documentation) - "...when this function is called no more data will be passed to the callbacks".

Do you know why tests start to fail? it can be correlated with expected output format

I haven't yet investigated, but here are some of the errors.

    (14/15) [ EXPECT] (X) See '123 F1' result in quickfix
      - Expected:
          || 123 F1
      - Got:
          || F1
    (15/15) [EXECUTE] Run test_app target with mask arguments
    (15/15) [ EXPECT] (X) See 'F1' result in quickfix
      - Expected:
          || --gtest_filter=Test* F1
      - Got:
          || F1

My next step will be moving the check if empty(s:cmake4vim_job) in utils#exec#job#run, and removing it from s:vimOut.

Answer 29 · 2021-04-19T10:35:15.000Z

Ah, figured out the problem. I should first call s:createQuickFix(), and then reset the s:cmake4vim_job. Now all the tests pass.

Anyway, try it out and let me know what you think, this seems to fix the dropped messages problem, at least for me.