Progress not showing up before the last second

I've implemented the Progress class to implement a nice progress bar:

https://github.com/guyzmo/git-repo/blob/master/git_repo/services/service.py#L46-56

I'm then using it, for example here:

https://github.com/guyzmo/git-repo/blob/master/git_repo/services/service.py#L196-202

And then, when I clone a very large repository (like mozilla's gecko):

% git hub clone mozilla/gecko-dev
Pulling from github |████████████████████████████████|
Successfully cloned `https://github.com/guyzmo/git-repo` into `./git-repo`!

the progress bar is "progressing" (i.e. incrementing from 0 to 100%), but it shows up only at the very end of the fetching, after hanging for a long while. I started to debug it, and it looks like it's related to subprocess stuff.

Though, I might be implementing it wrong, which is why I'm asking here while I'm still debugging that issue.

I think I'm onto something, I stopped with pdb to watch at the type of proc.stderr, and found out that proc.stderr.mode is 'rb', so it's binary buffering, and it's unlikely to have universal line ending enabled.

Then I went on to read subprocess documentation where it says:

Popen.stderr

If the stderr argument was PIPE, this attribute is a readable stream object as returned by open(). Reading from the stream provides error output from the child process. If the universal_newlines argument was True, the stream is a text stream, otherwise it is a byte stream. If the stderr argument was not PIPE, this attribute is None.

so I guess it's worth trying with Popen(..., universal_newlines=True)!

yay, it's what was the issue \o/

http://asciinema.org/a/5n0tyv6jmvu14u8lsi18f53c5

there's a bunch of caveats, though, because now proc.stderr lines are not bytes anymore, but unicode str.

Looks very good ! I am currently experimenting with adding this option just for fetch/push operations, and it doesn't seem too straightforward for some reason. Let's see how it goes.

Though, as a side effect the fetching is quite terribly slow, certainly of the overhead of going twice to stdout.

Why is it going through stdout twice ? And even if so, it's just a few hundred lines at most, and I wouldn't expect this to be noticeable. If it is, it might be something with regular expressions being slow ? Just guessing though.

well, from git's stdout to GitPython, and from GitPython to stdout!

That is something I would then consider a bug in either codebase, and hopefully fixable.

here's a summary of my patch:

modified: git/cmd.py
@@ -608,6 +608,7 @@ class Git(LazyMixin):
                          stdout=with_stdout and PIPE or open(os.devnull, 'wb'),
                          shell=self.USE_SHELL,
                          close_fds=(os.name == 'posix'),  # unsupported on windows
+                         universal_newlines=True,
                          **subprocess_kwargs
                          )
         except cmd_not_found_exception as err:
@@ -661,18 +662,15 @@ class Git(LazyMixin):
                         stderr_value = 'Timeout: the command "%s" did not complete in %d ' \
                                        'secs.' % (" ".join(command), kill_after_timeout)
                 # strip trailing "\n"
-                if stdout_value.endswith(b"\n"):
-                    stdout_value = stdout_value[:-1]
-                if stderr_value.endswith(b"\n"):
-                    stderr_value = stderr_value[:-1]
+                stdout_value = stdout_value.rstrip('\n')
+                stderr_value = stdout_value.rstrip('\n')
                 status = proc.returncode
             else:
                 stream_copy(proc.stdout, output_stream, self.max_chunk_size)
                 stdout_value = output_stream
                 stderr_value = proc.stderr.read()
                 # strip trailing "\n"
-                if stderr_value.endswith(b"\n"):
-                    stderr_value = stderr_value[:-1]
+                stderr_value = stdout_value.rstrip('\n')
                 status = proc.wait()
             # END stdout handling
         finally:

modified: git/remote.py
@@ -564,8 +564,9 @@ class Remote(LazyMixin, Iterable):

         progress_handler = progress.new_message_handler()

-        for line in proc.stderr.readlines():
-            line = line.decode(defenc)
+        for line in proc.stderr:
             for pline in progress_handler(line):
                 if line.startswith('fatal:') or line.startswith('error:'):
                     raise GitCommandError(("Error when fetching: %s" % line,), 2)

about the other errors, I just found out that I fscked up my local workspace, so to make a proper commit I need to do some cleaning first :)

fix(remote): use universal_newlines for fetch/push

I just pushed the universal_newline fix for remote operations. It should work, but please verify. For anything, I'd be happy to merge PRs you send this way.

Thanks for the asciicinema videos, it was nice to see the results of this work, and certainly helped my motivations :) !

fix(remote): py3 compatibility

I think this is fixed now:

GitPython/git/remote.py

Line 553 in 902679c

for line in proc.stderr:

.

ok, it looks like the "slowness" of my pulls might be caused by github throttling me, as I'm hammering them a bit too much:

git clone -v --progress https://github.com/gitpython-developers/GitPython  0.72s user 0.23s system 3% cpu 26.830 total
git hub -v clone gitpython-developers/GitPython  1.28s user 0.19s system 6% cpu 24.252 total

as I'm on a gigabit connection, I'm used to the clone being a lot less :)

Though, now that leaves us with this message showing up:

Fetch head lines do not match lines provided via progress information
length of progress lines 2 should be equal to lines in FETCH_HEAD file 1
Will ignore extra progress lines or fetch head lines.

any clues why it is happening? is it related to some other changes in master?

Yes, it's a fix for another issue, which if not there would have caused an assertion error.
It might also show that something is different now. Could you revert my previous two commits to see if the error still occours ?

It could be that indeed we get more progress lines than previously, thanks to the different split characters.

it's still happening with b9a7dc5 and b40d4b5 reverted. So I guess it's because of the new split mechanism. I guess we're including extra lines in one of l_fil and l_fhi... Now we just need to figure out what, and how to exclude them! :-)

You should be able to print these arrays to see what the difference is ... . Maybe an empty line snuck in there.

I'm doing a pdb.set_trace() to print them both, hang on :-)

BTW, are you on IRC, to avoid "chatting" over the comments and keep the essential here?

here it goes:

(Pdb) print(fetch_info_lines)
[' * branch            master     -> FETCH_HEAD\n', ' * [new branch]      master     -> github/master\n']
(Pdb) print(fetch_head_info)
["902679c47c3d1238833ac9c9fdbc7c0ddbedf509\t\tbranch 'master' of github.com:gitpython-developers/GitPython\n"]

for a pull, what I'm doing something is equivalent to:

repo = git.Repo.init('GitPython')
repo.create_remote('github', 'git@github.com:gitpython-developers/GitPython')
repo.create_remote('all', 'git@github.com:gitpython-developers/GitPython')
repo.pull('master', progress=pb)

So the new branch isn't handled as it is not part of the information git puts into the FETCH_HEAD.
I really don't know what the rule is there, but believe the warning can be ignored for now.

Also what I understand is the my two recent commits didn't affect this issue, so we wouldn't have to be concerned with it here.

Does it mean we do have real-time progress now ?

Does it mean we do have real-time progress now ?

I guess we can say so!

So the new branch isn't handled as it is not part of the information git puts into the FETCH_HEAD.
I really don't know what the rule is there, but believe the warning can be ignored for now.

well, maybe should we downgrade the warning to debug logging, so it's not in the way looking bad when doing a pull when not in verbose mode? :-)

Good idea ! Would you like to do a PR, just to have your name baked permanently into the authors list of this project :) ?

Changing warning to debug logging, to avoid warning showing off when …

done :)

BTW, you don't really need to include that PR, as I already had a PR merged, and a new one I just did to be merged :-)

Thank you ! I am super happy to finally see this feature implemented right. Even though I implemented it for my own use, I never got around to actually using it, and thus didn't notice the various shortcomings you now discovered.

I have to admit that I've implemented the feature mostly because I saw the progress parameter to the function and found it fun to implement (I also liked very much the progress bar of pip, so I thought why not do it the same way? :-) ). Anyway, it looks like we've nailed it 👍

BTW, if you're on IRC, don't hesitate to ping me, I'm zmo on freenode.

@Byron

@Byron I thought this was fixed. I'm not seeing the problem any more. Can this issue me closed?

worksforme ☺

We can close it then, fixed under the milestone it is currently under!
Thanks.

(do you want to push any AUTHOR changes?)

sure thanks, I'll do that in a currently pending PR I'm pushing!

Not sure if I should file a new bug or resurrect this one, but an earlier comment says:

I am currently experimenting with adding this option just for fetch/push operations

Was cloning just overlooked? git.Repo.clone_from seems to have the exact same problem. I fixed it locally by changing git.remote.add_progress to also set kwargs['universal_newlines'] = True, and changing git.base.Repo._clone to pass decode_streams = False to handle_process_output

@mrozekma

@mrozekma I believe creating a new issue would be the way to go, while assuring the issue can be reproduced with the latest version.

fix(remote): real-time reading of lines from stderr

Navigation Menu

Repository navigation

Progress not showing up before the last second #444

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Progress not showing up before the last second #444

Description

Activity

guyzmo commented on May 26, 2016

guyzmo commented on May 26, 2016

Byron commented on May 26, 2016

guyzmo commented on May 26, 2016

Byron commented on May 26, 2016

guyzmo commented on May 26, 2016

Byron commented on May 26, 2016

guyzmo commented on May 26, 2016

Byron commented on May 26, 2016

Byron commented on May 26, 2016

guyzmo commented on May 26, 2016

guyzmo commented on May 26, 2016

Byron commented on May 26, 2016

guyzmo commented on May 26, 2016

Byron commented on May 26, 2016

guyzmo commented on May 26, 2016

guyzmo commented on May 26, 2016

Byron commented on May 26, 2016

guyzmo commented on May 26, 2016

Byron commented on May 26, 2016

guyzmo commented on May 26, 2016

Byron commented on May 27, 2016

guyzmo commented on May 27, 2016

barry-scott commented on Oct 11, 2016

guyzmo commented on Oct 11, 2016

ankostis commented on Oct 11, 2016

guyzmo commented on Oct 11, 2016

mrozekma commented on Aug 6, 2017

Byron commented on Sep 28, 2017

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions