juju 2.4.4 drops "executing operation" log message for starting hook

[Jason Hobbs]

In older versions, there was an easy to to spot (and grep for) message 'executing operation' when a hook started, and 'committing operation' when it ended. In 2.4.4, there appears to be no message when a hook ends, and only a "<hook-name> active" message when it starts.

It would be great if we had clear, easy to grep for messages indicating hooks starting/stopping.

[John A Meinel (jameinel)]

I wonder if this is related to the change that stopped creating an
status-history record for when update-status was triggered.

On Tue, Oct 9, 2018 at 7:40 PM Jason Hobbs <email address hidden>
wrote:

> Public bug reported:
>
> In older versions, there was an easy to to spot (and grep for) message
> 'executing operation' when a hook started, and 'committing operation'
> when it ended. In 2.4.4, there appears to be no message when a hook
> ends, and only a "<hook-name> active" message when it starts.
>
> It would be great if we had clear, easy to grep for messages indicating
> hooks starting/stopping.
>
> ** Affects: juju
> Importance: Undecided
> Status: New
>
>
> ** Tags: cdo-qa
>
> --
> You received this bug notification because you are subscribed to juju.
> Matching subscriptions: juju bugs
> https://bugs.launchpad.net/bugs/1796916
>
> Title:
> juju 2.4.4 drops "executing operation" log message for starting hook
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/juju/+bug/1796916/+subscriptions
>

[Richard Harding (rharding)]

Is this in the status output or the debug-log output?

[Jason Hobbs (jason-hobbs)]

It's in the unit log.

[John A Meinel (jameinel)]

With current 2.4 branch this is what I see:
unit-ul-0: 17:12:40 DEBUG juju.worker.uniter.operation running operation
run install hook
unit-ul-0: 17:12:40 DEBUG juju.worker.uniter.operation preparing operation
"run install hook"
unit-ul-0: 17:12:40 DEBUG juju.worker.uniter.operation executing operation
"run install hook"
unit-ul-0: 17:12:40 DEBUG juju.worker.uniter [AGENT-STATUS] executing:
running install hook
unit-ul-0: 17:12:40 INFO juju.worker.uniter.operation skipped "install"
hook (missing)
unit-ul-0: 17:12:40 DEBUG juju.worker.uniter.operation committing operation
"run install hook"
un

As far as I can tell, these are the same messages that you get for Juju
2.3. Is it a case where you had a different logging-config that exposed
them and that got disabled in 2.4.4?

On Tue, Oct 23, 2018 at 1:16 PM Richard Harding <email address hidden>
wrote:

> ** Changed in: juju
> Status: New => Triaged
>
> ** Changed in: juju
> Importance: Undecided => High
>
> ** Also affects: juju/2.4
> Importance: Undecided
> Status: New
>
> ** Changed in: juju
> Milestone: None => 2.5-beta1
>
> ** Changed in: juju/2.4
> Status: New => Triaged
>
> ** Changed in: juju/2.4
> Importance: Undecided => High
>
> ** Changed in: juju/2.4
> Milestone: None => 2.4.5
>
> --
> You received this bug notification because you are subscribed to juju.
> Matching subscriptions: juju bugs
> https://bugs.launchpad.net/bugs/1796916
>
> Title:
> juju 2.4.4 drops "executing operation" log message for starting hook
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/juju/+bug/1796916/+subscriptions
>

[Jason Hobbs (jason-hobbs)]

I don't think we've changed logging-config. What would turn those on or
off? We have DEBUG level messages.

On Tue, Nov 6, 2018 at 3:41 PM Canonical Juju QA Bot <
<email address hidden>> wrote:

> ** Changed in: juju/2.4
> Milestone: 2.4.5 => 2.4.6
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1796916
>
> Title:
> juju 2.4.4 drops "executing operation" log message for starting hook
>
> Status in juju:
> Triaged
> Status in juju 2.4 series:
> Triaged
>
> Bug description:
> In older versions, there was an easy to to spot (and grep for) message
> 'executing operation' when a hook started, and 'committing operation'
> when it ended. In 2.4.4, there appears to be no message when a hook
> ends, and only a "<hook-name> active" message when it starts.
>
> It would be great if we had clear, easy to grep for messages
> indicating hooks starting/stopping.
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/juju/+bug/1796916/+subscriptions
>

[Tim Penhey (thumper)]

I just checked with 2.5.3 and definitely have both the lines mentioned:

unit-ubuntu-0: 11:13:05 DEBUG juju.worker.uniter.operation executing operation "run leader-elected hook"
unit-ubuntu-0: 11:13:05 DEBUG juju.worker.uniter [AGENT-STATUS] executing: running leader-elected hook
unit-ubuntu-0: 11:13:05 INFO unit.ubuntu/0.juju-log Reactive main running for hook leader-elected
unit-ubuntu-0: 11:13:05 INFO juju.worker.uniter.operation ran "leader-elected" hook
unit-ubuntu-0: 11:13:05 DEBUG juju.worker.uniter.operation committing operation "run leader-elected hook"

[Launchpad Janitor (janitor)]

[Expired for juju 2.4 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for juju because there has been no activity for 60 days.]