When using SSHKit 1.7.1, airbrussh duplicates command output
mattbrictson opened this issue · 9 comments
Notice here that "Fetching origin" is printed twice. It only appears once in the actual output when the command is run on the server.
00:05 git:update
02 git remote update
02 Fetching origin
02 Fetching origin
This is probably due to the extra .dup call added in 73ec3e7.
Does this occur against master or only against the older versions where the flow goes via the write method?
I think it might be a problem with log_command_data not being guarded by first_execution?. I am taking a look at this now.
@mattbrictson Are you working on anything at the moment? Happy to look at this, but don't want to tread on your toes if you are already on it!
@robd No, I'm not working on anything at the moment. Go for it!
I think the problem here is that the new DelegatingFormatter calls dup for every formatter before passing the duped value to write. That means that when e.g. stdout is cleared, it clears it on the duped command but never the original command.
Before the refactor, Formatter would call dup for the command sent to the log file, but it would use the original command object for it's own purposes.
So I think the solution here is to change the "dup and forward" logic so that the last formatter gets the original object, and the others get dupes.
And yes, in my testing this only affects 1.7.1 (which uses write) and not master.
The mystery is why this isn't being caught in the acceptance tests. Perhaps it is due to some internal difference in the local and net-ssh backends.
Ahh OK, I see - thanks for the steer. I will look into it and work out what test is missing, and try to fix it or report back on my findings.
Ah OK - yes you are absolutely correct. I think you basically groked all of this already, but just to check we're on the same page, here's my understanding of what's going on:
The Local backend in version 1.7.1 has additional calls to clear the command output when the command exits, wheras the NetSSH one doesn't.
Before, when running with NetSSH, we passed the dup to the Pretty formatter, and relied on the fact that the Airbrussh formatter cleared the output on the original command. This meant that, when the command came back into the write method the next time, the output had been cleared.
This doesn't show up in the acceptance tests because of the additional methods on the Local backend which clear the output, so as you say, no way to test this with the existing, Local backend based acceptance test.
Do you think it matters which order the backends are called in? I notice you explicitly added in the the LogFileFormatter before the ConsoleFormatter one (as opposed to simply appending it). Was there a reason for this or was it just to try to maintain existing behaviour?
As for a fix, I guess we have a choice of which backend to pass the original command to. To maintain existing behvaiour, we should pass it to the ConsoleFormatter and pass the dup to the LogFileFormatter. But I am tempted to pass the original command to the LogFileFormatter instead because this would mean that we would no longer need to clear the command output in the ConsoleFormatter.
@mattbrictson What do you think?
Great detective work on the net-ssh vs local backends! I think all of this is proving that the refactor of SSHKit to use log_command_output instead of write was a much-needed improvement. Too bad we still have to support 1.7.1.
Do you think it matters which order the backends are called in? I notice you explicitly added in the the LogFileFormatter before the ConsoleFormatter one (as opposed to simply appending it). Was there a reason for this or was it just to try to maintain existing behaviour?
Yes, I was just trying to maintain existing behavior. I don't think the order necessarily matters, but I think maybe ConsoleFormatter should get the duplicate command and LogFileFormatter should get the original command. Since ConsoleFormatter ignores debug commands, that means it won't be clearing the output for those. Whereas Pretty will clear the output for all commands, including debug ones. So it is probably the more reliable target for the original command object.
We can't remove the logic that clears the output from ConsoleFormatter, though, because depending on configuration there may not be a LogFileFormatter present. So we can't rely on it always being there to clear the output for us.
OK, yes - very good points. I will get a PR together to fix this.
@mattbrictson OK, I tried this branch manually on a test project and the duplicate output is now gone. 👍 I tried to explain what's going on in the comments, but I'm a bit tired now, so see what you think. I may be able to look into #44 tomorrow evening, I will comment there if I start looking at that issue.
@mattbrictson I think this is fixed in #46. If you have a chance, could you could confirm and close this issue?
Closed via #46.