Problem/Motivation

drupalci relies on a static Output class to manage telling things to the user.

There are a number of problems with this:

Proposed resolution

  • Add a container to aid with injection: #2638466: Add a php container to make the codebase easier to test. (this issue is effectively postponed on that one)
  • Inject the container and/or output object down the calling chain.
  • Replace calls to Output with calls to the injected output.
  • Determine how to handle Output::error().
  • Update symfony/console to 2.8 so we can use the new styles feature. This requires an upstream change to nickschuch/privatetravis, which has a hard version constraint on console which seems arbitrary.

Remaining tasks

User interface changes

API changes

Data model changes

Comments

Mile23 created an issue. See original summary.

mile23’s picture

Issue summary: View changes
mile23’s picture

Issue summary: View changes
mile23’s picture

Asked Nick to bump up the console version: https://github.com/nickschuch/PrivateTravis/issues/35

jthorson’s picture

PrivateTravis isn't currently used in the codebase - it may still be useful for travis.ci file compatibility in the future, but don't postpone on any PrivateTravis dependencies in the meantime.

jthorson’s picture

Oh ... and a big +1 to the style features!!!

mile23’s picture

OK, so if privatetravis isn't really a dependency, then lets pull it from composer.json.

jthorson’s picture

Status: Active » Needs review

Work pushed to 2642636-introduce-logger branch.

jthorson’s picture

So far:
- Added LoggerProvider (using standard Console logger)
- Converted Build, Run, Pull, Status, DockerRemove and DrupalCICommandBase to use logger

  • jthorson committed ac8f8a3 on 2642636-introduce-logger
    Issue #2642636 by jthorson: Converted remaining Console Commands to use...
mile23’s picture

Before we get too far down this road, let's add some tests so we're sure we're not leaving a trail of spare parts: #2676854: [meta] Write functional tests to prevent regressions

jthorson’s picture

That's a hell of a catch-22 ... We can't write effective tests until we decouple the code, and we can't decouple the code until we have tests.

I'm not really interested in writing tests for coverage of things that we're trying to rip out. This work starts to give us the decoupling needed to write effective tests ... and while I agree that having tests would be ideal, that task becomes much easier AFTER this work goes in.

For what it's worth, I perform a full end-to-end test run as a functional test before ever posting my work here ... and I'm growing more than a little frustrated with the combination of "We need to restructure because we can't build effective tests" and "We can't change until the tests are written" messages I keep hearing.

Mixologic’s picture

Full 'end-to-end' test is inadequate to establish that changes do not introduce functional regressions, as it only exercises a single path through the system. What we're aiming to have is a real 'end-to-end' test that excerises all the edge cases in the system, in an automated fashion.

Right now, we aren't planning on ripping out any functionality, we're planning on restructuring code and refactoring things to reduce coupling, and improve maintainability, and additionally, add functionality. But what the code actually *does* still needs to work, so we need to set up the way we're going to prove that it does.

The *only* major refactoring we'd really want to do right now is something that can get us multiple separate jobs (i.e. run simpletest and run phantomjs as part of the same run).

So, given that, if we start building tests around what drupalCI currently does, we can continue to prove that it does what it needs to do, thus giving us confidence that we can accept changes moving forward. Certainly some tests will break if we change what we're doing, and they are supposed to.

And to be clear, we're not talking about writing unit tests for granular classes, we're talking about writing functional tests that prove that given a particular configuration, drupalci can effectively run tests and produce expected output.

jthorson’s picture

... prove that given a particular configuration, drupalci can effectively run tests and produce expected output.

So ... essentially, what you're saying is that, given a particular configuration, we want to ensure that we can run tests and produce expected output ... which ...

... is inadequate to establish that changes do not introduce functional regressions, as it only exercises a single path through the system.

As I said ... it's really quite difficult rationalizing the conflicting messages. :)

dawehner’s picture

Well the point of end-to-end tests are that you are able to cover the basic usecase of a system. By definition they don't cover all edge cases, but they are really not the point of it. I really don't see why a end-to-end test would be problematic. It helps to cover really problematic regressions quickly.

jthorson’s picture

To be clear, I'm not arguing against implementing automated end-to-end tests ... my point is that, in the absence of such a test existing today, we should not be blocking code which simplifies the the overall testing effort and provides us the decoupling that we're looking for, based solely on the argument that "We might introduce regressions".

It takes about 45 seconds to manually execute an end-to-end simpletest test run (i.e. on a single test group), which gives us the same level of test coverage and same assurance that we have not introduced any regressions as we would get from an automated functional end-to-end test based on the same inputs. I've been hearing "We need more tests" for six months now, and they haven't been materialzing ... this mantra is stifling innovation and putting a significant drag on the addition of new features into the project. Code (such as support for testing on minor php versions) has sat in the queue for 6 months with no review, because we're being told "It's not worth reviewing until we have tests." Yes ... automated testing would be ideal. No ... we should not stall all further progress on the codebase based on 'we need tests first'. Instead, we should press ahead with the refactoring, and add the desired testing in parallel with those efforts ... The amount of time saved by having those tests available in advance is not justified relative to i) the amount of effort required to add them now relative to the effort to add them after the code is restructured, ii) the amount of rework those tests will require after the refactoring, iii) a minimal gap in coverage between the proposed automated tests and manual end-to-end test runs, and iv) the drag on new feature functionality we are creating in the meantime.

The above is why I'm advocating for the strategy outlined in #2678462: "Queued Code" Cleanup and Test Development Strategy.

mile23’s picture

Status: Needs review » Needs work

Rebased from dev now that #2679673: Create minimal functional tests of command output to test Output refactoring is in.

There are a couple fails in the tests:

$ ./bin/phpunit 
PHPUnit 3.7.38 by Sebastian Bergmann.

Configuration read from /home/vagrant/drupalci_testbot/phpunit.xml

.............................F.F....

Time: 7.76 seconds, Memory: 13.75Mb

There were 2 failures:

1) DrupalCI\Tests\Console\Command\PullCommandTest::testPull
Failed asserting that '[notice] Pulling foof:latest container
' matches PCRE pattern "`Executing pull ...`".

/home/vagrant/drupalci_testbot/tests/DrupalCI/Tests/Console/Command/PullCommandTest.php:29

2) DrupalCI\Tests\Console\Command\Status\StatusCommandTest::testStatus
Failed asserting that '[info] Running Status Checks ...
Checking Docker Version ... 
Docker version: Docker version 1.10.2, build c3959b1

[info] No errors found!
' matches PCRE pattern "/Running Status Checks ... \nChecking Docker Version ... \n/".

/home/vagrant/drupalci_testbot/tests/DrupalCI/Tests/Console/Command/Status/StatusCommandTest.php:16

FAILURES!
Tests: 36, Assertions: 47, Failures: 2.
vagrant@vagrant-ubuntu-trusty-64:~/drupalci_testbot$

They seem to be related to doing the right thing, fundamentally. So there you go.

  • Mile23 committed 0f59ce7 on 2642636-introduce-logger authored by jthorson
    Issue #2642636 by jthorson: Convert Build, Run, Pull, Status,...
  • Mile23 committed 673b14c on 2642636-introduce-logger authored by jthorson
    Issue #2642636 by jthorson: Introduce LoggerProvider
    
  • Mile23 committed cb1025a on 2642636-introduce-logger
    Issue #2642636 Rebase from dev.
    
  • Mile23 committed de39bcc on 2642636-introduce-logger authored by jthorson
    Issue #2642636 by jthorson: Converted remaining Console Commands to use...

  • jthorson committed 0857342 on 2642636-introduce-logger
    Issue #2642636 by jthorson: Fix tests to be compatible with logger...
jthorson’s picture

Status: Needs work » Needs review

Tests fixed.

  • Mile23 committed 16ba85f on 2642636-introduce-logger
    Issue #2642636: More stability for RunCommandTest.
    
mile23’s picture

   public function execute(InputInterface $input, OutputInterface $output) {
     Output::setOutput($output);
-    $output->writeln("<info>Executing build ...</info>");
+    $this->logger->info("<info>Executing build ...</info>");

I'm not sure this is the right pattern, because all output will now say [info] or [notice] or whatever next to it. It might be an aesthetic choice, but yah.

After a little brittle time with RunCommandTest, I changed it to load the blank config and added a @todo about #2683013: Better functional test framework

mile23’s picture

Assigned: Unassigned » mile23

Doing some work on this...

mile23’s picture

Assigned: mile23 » Unassigned

Added branch 2642636-remove-static-output which is different from 2642636-introduce-logger.

It just injects whatever output is present into each item.

It changes only the environment build step, because I was interested in reading that one. :-)

It adds tests to check the output either way.

I modified Output::error() to accept an output object, with a @todo about changing that later.

Basically: I think we shouldn't use the logger for console output. We can tee it to a file with our own implementation of OutputInterface at some point, or just let Jenkins pipe STDOUT wherever it wants to go.

jthorson’s picture

Basically: I think we shouldn't use the logger for console output. We can tee it to a file with our own implementation of OutputInterface at some point, or just let Jenkins pipe STDOUT wherever it wants to go.

So this reads as an argument that we shouldn't use logger simply because it's possible to do something else. Can you elaborate with reasons to not use logger, specifically?

The reason I went with logger were:

  1. It's included in Symfony console by default, which should make it a 'familiar' implementation for anyone with Console experience,
  2. It's a standard (PSR-3) implementation, but still lightweight; saving us the need to build our own implementation,
  3. Built in support for console's multiple verbosity levels, without having to wrap every Output call in a if (Output->getVerbosity() >= OutputInterface::VERBOSITY_VERBOSE) check,
  4. It addresses each of the concerns identified in the issue summary,
  5. It's easier than building and maintaining our own Output object to do the same thing, and
  6. It gives us the option to swap it out for Monolog in the future, which would then also give us things like:
    • - automatic timestamping,
    • - stdout vs stderr routing,
    • - multiple custom channels (perhaps build email notification content on the fly during the run; or write infrastructure-related errors to a monitored log)
    • - custom formatters (via configuration instead of code), and
    • - real-time output via monolog Streamhandlers.

  • Mile23 committed 004982a on 2642636-remove-static-output
    Issue #2642636: Remove static Output: Replacement in environment step...

  • jthorson committed b4b98fe on 2642636-introduce-logger authored by Mile23
    Issue #2642636: More stability for RunCommandTest.
    

  • jthorson committed 2978956 on 2642636-introduce-logger
    Issue #2642636 by jthorson: Move logger instantiation to...
mile23’s picture

Status: Needs review » Needs work

So this reads as an argument that we shouldn't use logger simply because it's possible to do something else. Can you elaborate with reasons to not use logger, specifically?

Other than the two reasons I already gave?

Calling $this->logger->whatever() means we can't use OutputInterface. If we want styles and interaction we're stuck. And we want those things.

Instead, inject $output into all places that need it. Then any $output object can tee to the log or just log or whatever.

Also, [info] Hi there. looks awful.

jthorson’s picture

Okay ... for the style guides, we can get the same value using Monolog's OutputFormatter, but I'll cede to your point that the logger would complicate interaction and the use of the various Question console helpers.

For me, the biggest goal was to eliminate the need to wrap each line of output in a verbosity check to support differentiated verbosity level output ... With this approach, we could achieve the same by extending SymfonyStyle to add an optional 'verbosityLevel' argument and associated verbosity level check inside each of the appropriate output methods; which should eliminate a lot of verbose (pun intended) code ... Thoughts?

And the other logger benefits I identified above could be realized by injecting a logger service either inside or parallel to the SymfonyStyle $io component at some point in the future.

Mixologic’s picture

This: http://symfony.com/doc/current/cookbook/logging/monolog_console.html sounds like what jthorson is describing, with alternate pointers to the PSR3 logging method (http://symfony.com/doc/2.8/components/console/logger.html).

So, what this comes back to is doing one thing at a time, and not trying to do multiple things at once. The immediate goal is to get rid of the static output class and replace it with something sane, and built in.

We aren't exactly dying for verbosity control, but it woudn't hurt to have that feature either. New features, however, should have an agreed upon strategy before implementing - even in this case we've got a couple of choices, (monolog vs psr3) and have a lot of decisions to make regarding what levels each output needs to be set at. None of that discussion has happened, and none of it should hold up the goal of this issue when it does.

My thoughts is that we move forward with Mile23's switchout, open up a followup issue for the verbosity feature, and lean towards the monolog implementation vs the psr3 implementation given the formatting flexibility it gives us.

jthorson’s picture

With all due respect, those conversations HAVE happened ... they just happened before you assumed the gatekeeper role. Just because you weren't at the table at the time, please don't presume that there isn't a sound strategy behind my proposed changes.

Doing things one thing at a time is precisely why I implemented the PSR3 logger instead of going straight to Monolog ... this approach allows us to replace the static Output object with a lightweight alternative *for now*, in such a way that the move to Monolog *in the future* becomes a 'drop-in' replacement, as opposed to a new round of code refactoring. (Thus the value of using a 'standard' log interface ...)

EDIT: Re-reading this comment, it felt like it could be construed as reversing my stance in #30 ... For the sake of clarity, those comments hold and I'm on board with the approach as described.

Mixologic’s picture

mile23’s picture

Assigned: Unassigned » mile23

Okay ... for the style guides, we can get the same value using Monolog's OutputFormatter

Well, no, we can't. Or maybe we could, but then we'd be unfuzzling a thing we fuzzled when we could have not fuzzled it in the first place.

We'll also be able to add our own style guide, which will be an opportunity to add a convenient verbosity check.

The step here is to inject output. I'll assign it to myself and continue work on 2642636-remove-static-output

  • Mile23 committed 631522b on 2642636-remove-static-output
    Issue #2642636: Remove static Output: Replacement in environment step...

  • Mile23 committed 32e09bc on 2642636-remove-static-output
    Issue #2642636: Injected output to all build step plugins.
    

  • Mile23 committed 5f03b26 on 2642636-remove-static-output
    Issue #2642636: All output injected.
    
mile23’s picture

Assigned: mile23 » Unassigned
Status: Needs work » Needs review

The Output static class is still present so we can use Output::error().

Output::error() now takes an optional parameter of OutputInterface, so an output object can be injected.

All other usages of Output are deprecated for an injected output object.

  • Mile23 committed c84528f on 2642636-remove-static-output
    Issue #2642636: Removed error_log()
    
Mixologic’s picture

Component: DrupalCI console script » Testrunner Codebase

  • Mile23 committed f6c70ba on 2642636-remove-static-output
    Issue #2642636: Merge branch 'dev' into 2642636-remove-static-output
    

  • Mile23 committed a27bec9 on 2642636-remove-static-output
    Issue #2642636: Expanding IoC injection.
    
  • Mile23 committed aed2e85 on 2642636-remove-static-output
    Issue #2642636: More direct injection, disusing InjectableTrait
    
mile23’s picture

Moving away from the InjectableTrait idea, because injecting the services at the proper level is much better.

  • Mile23 committed 8c14487 on 2642636-inject-io
    Issue #2642636: DrupalCIStyle.
    
  • Mile23 committed 9af0f86 on 2642636-inject-io
    Issue #2642636: Injected Style IO service.
    
mile23’s picture

Added a new branch called 2642636-inject-io.

In this version we're making a console.io service and injecting it everywhere. It replaces most usages of Output::writeln().

console.io ends up being a DrupalCIStyle object, which sublcasses SymfonyStyle in order to add a drupalCIError() method. This way we can emulate the style of Output::error().

Mixologic’s picture

Mixologic’s picture

Okay, I did sortof a boo boo. I merged this into dev, instead of the other way around. So after I fixed all of the merge conflicts, and adjusted everywhere else I needed to, and made things work with the FileHandlerTrait that was a plugin before, and moved some things around to support ContainerCommands as Build Objects, This is now passing tests, and shoehorned in.

I also went around cleaning up the 77 OPUT's I put everywhere. Not sure why I did that. There's still a few in DockerPullCommand that Im not quite sure I want to figure out or just eliminate entirely (passing progressbars to the init command)

Mixologic’s picture

Status: Needs review » Fixed

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.