Package Manager should keep an audit log of changes it applied to the active codebase

Wim Leers → credited phenaproxima → .

Wim Leers → credited tedbow → .

A new subscriber that listens to PreRequireEvent to log which package changes were requested

I don't there should be any logging until PostApply. Update until point we don't know if these change will be actually be applied to the site. The operations may be canceled or not validate on Pre-Apply. We can subscribe to PreRequire and keep a record of what was request to compare against what the final packages that are changed..

I think it would confusing to have the PreRequireEvent logging package changes that never actually get applied to the site.

Create a follow-up for a Drush command that makes it easy to inspect the audit log, based on what we learn here along the way

I think this follow-up should the priority of "minor" because this won't be part of the core module. So anything we can do for the core module should be be a higher priority. We could file core issue to provide a drupal log command. Could have a channel option so we could do drupal log -channel=package_manager_audit_log

We can subscribe to PreRequire and keep a record of what was request to compare against what the final packages that are changed..

👍

I think it would confusing to have the PreRequireEvent logging package changes that never actually get applied to the site.

💯

I think this follow-up should the priority of "minor"

Sure. But … it will be critical for adoption/support by hosting companies, because this would make their job of supporting customers actually manageable.

This would also really help with debugging/writing the Build test over at 📌 [PP-1] Implement experimental cron updates for contrib in automatic_updates_extensions Postponed .

This is on the right track!

High-level next steps:

1. I think the current MR is interpreting the issue summary a bit too literally, which is why it currently only works for UpdateStage instances and not all StageBase instances. Explained on the MR how that can be supported 😊
2. 
   

       $this->auditLogger = new TestLogger();
       $this->container->get('logger.channel.package_manager_audit_log')
         ->addLogger($this->auditLogger);
   

3. Nope, that can't work, because none of the Kernel tests execute a whole stage life cycle 🙈
4. Attempt #2! As for how to adopt this and start using it in tests: \Drupal\Tests\package_manager\Build\TemplateProjectTestBase::assertExpectedStageEventsFired() provides an example! That is using the test-only package_manager_test_event_logger (which is still valuable on its own). This MR needs to add a TemplateProjectTestBase::assertPackageManagerAuditLog() method with logic modeled after ::assertExpectedStageEventsFired().
5. 100% of build tests should be updated to use it — that means 5 classes should gain a ::assertPackageManagerAuditLog() all the way at the end.

#16 helped me discover the need for 🐛 Document that validators comparing state between stage life cycle operations must store that state out-of-band, not on the object Closed: outdated 👍😄

Some of the failures are because of the exception Typed property Drupal\package_manager\EventSubscriber\ChangeLogSubscriber::$installedPackagesBeforeApply must not be accessed before initialization during post-apply as I am accessing it in \Drupal\package_manager\EventSubscriber\logAppliedChanges. But it is getting set in \Drupal\package_manager\EventSubscriber\recordInstalledPackagesBeforeApply which runs on pre-create which definitely runs before post-apply and we shouldn’t get this error. But I think the error is because the post-apply is running on different request and it can't access that property. And actually this property is also accessed in \Drupal\package_manager\EventSubscriber\logRequestedChanges which runs on post-require and it works fine.

Two nits, otherwise looks good, nice work✌️

Looking great! 👏 😄

I requested some changes (pun intended 😜) to help improve test code clarity. But this is definitely close to being done!

Credited @omkar.podey for the review.

I found more room for simplification!

99% ready!

No more need for a follow-up for a Drush command: I discovered drush watchdog:list --type thanks to @tedbow's comment #8.

Great to have this done!

I really like the idea here, but I think some clean-up is warranted.

Nice catches from @phenaproxima. Found a few new inconsistencies now — see the MR.

The build tests are failing because of 📌 Since #3361983 was committed to Drupal core, psr/http-message needed to be explicitly required for build tests Needs work

Once tests are passing again (after 📌 Since #3361983 was committed to Drupal core, psr/http-message needed to be explicitly required for build tests Needs work lands), this can be committed 👍

I would like to review and commit this. Will be great to get this in!

See MR comment

🏓 See MR comment: https://git.drupalcode.org/project/automatic_updates/-/merge_requests/86...

Unassigning from myself since I responded to @Wim Leers' points.

I don't think we should expand this issue any further and don't think the current log messages give enough context to the user reading the logs to understand that the "required" changes may or may not actually related to changes that made to the active site(see my MR comments). I think we would need to expand this issue a lot to make including the messages from updates that did not succeed or were canceled to be understandable by people were not involved in developing this module.

for that reason I think in this issue we should only every add a long message in PostApply. We can use information we gathered from subscribe to the other events but we should not log anything in those other events.

That will fulfill the primary purpose of the of the issue which is let the admin know what projects have been changed by Package Manager.

I updated the title to match this

think we would need to expand this issue a lot to make including the messages from updates that did not succeed or were canceled to be understandable by people were not involved in developing this module.

Fair!

That will fulfill the primary purpose of the of the issue which is let the admin know what projects have been changed by Package Manager.

WFM

Found some problems during re-reviewing.

I think we still have some clarifying to do here, and I'm wondering if we can't make the whole thing slightly simpler.

For @phenaproxima's feedback.

One last piece of feedback.

P.S.: Those new commit messages are WAY better! 👏

🚀

I wondering if this would be easier to test in a kernel.

We can use our fixture manipulators to fake which versions get updated.

The reason I was wondering is because right now we don't test that nothing gets logged if the process is stopped in preapply or before. maybe we don't need to test this but it would be pretty easy in kernel test but very hard in a build test. Maybe we could that in follow-up

@phenaproxima had mentioned in wanted to review before I committed so assigning him.

The reason I was wondering is because right now we don't test that nothing gets logged if the process is stopped in preapply or before

If this were critical logic, I'd get it. But it's just logging.

maybe we don't need to test this but […]

I don't think we need to test this.

The complexity of testing would far outweigh the complexity of the logging. Plus, a bug in the logging cannot even break the functionality itself. Hence no tests for edge cases necessary, only for The Happy Path.

phenaproxima → credited wendyZ → .

Crediting @wendyZ for 🐛 [DrupalCon] Automatic Updates alpha test result Fixed .

To clarify #55: @wendyZ specifically requested this behavior; they were surprised it did not already happen, thus confirming the need for this functionality — here's what they wrote:

But the whole update process was not logged at all. By looking at the log report, it only shows the 2 auto_updates modules are installed. It should also log the core was upgraded from which version to version.

There are some core things here that I don't think I'm understanding.

Looking good!

A few points in the MR

Just 2 more things

🤣I didn't mean to RTBC it before but now it looks done!

thanks everyone!

uggh. we have phpstan error only in 10.0.x for some reason https://www.drupal.org/pift-ci-job/2692141 →

The error is real not sure why phpstan didn't catch it

    // The first record should be of the requested changes.
    $expected_message = <<<END
Requested changes:
- Update drupal/core-recommended from 9.8.0 to ^9.8.1
- Install drupal/semver_test * (any version)
END;
    $this->assertSame($expected_message, (string) $records[0]['message']);

    // The second record should be of the actual changes.
    $expected_message = <<<END
Applied changes:
- Updated drupal/core from 9.8.0 to 9.8.1
- Updated drupal/core-dev from 9.8.0 to 9.8.1
- Updated drupal/core-recommended from 9.8.0 to 9.8.1
- Installed drupal/semver_test 8.1.1
- Uninstalled package/removed
END;
    $this->assertSame($expected_message, (string) $records[1]['message']);

🤩

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