diskimage retrofit action fails several times with simplestreams already synced on images

[Pedro Guimarães]

Hi,

glance-simplestreams-sync has been synced for 20 minutes: https://pastebin.ubuntu.com/p/tPgs52P8DH/

And still, when I run the action it results on:

$ juju run-action --wait octavia-diskimage-retrofit/leader retrofit-image
unit-octavia-diskimage-retrofit-0:
  UnitId: octavia-diskimage-retrofit/0
  id: "15"
  message: '''NoneType'' object is not iterable'
  results:
    Stderr: |
      All snaps up to date.
    Stdout: |
      lxc
  status: failed
  timing:
    completed: 2020-02-27 07:55:51 +0000 UTC
    enqueued: 2020-02-27 07:55:45 +0000 UTC
    started: 2020-02-27 07:55:46 +0000 UTC

Looking at the logs, one can see it was ran way later than simplestreams was synced:
2020-02-27 07:55:47 DEBUG juju-log Running action "retrofit-image"
2020-02-27 07:55:47 INFO juju-log DEPRECATION WARNING: Function action_get is being removed : moved to function_get()
2020-02-27 07:55:50 ERROR juju-log action "retrofit-image" failed: "'NoneType' object is not iterable"
2020-02-27 07:55:50 INFO juju-log DEPRECATION WARNING: Function action_fail is being removed : moved to function_fail()

Full retrofit logs: https://pastebin.canonical.com/p/D6TRQTdFYS/

I still can see that charm eventually moved to "maintenance" status and "Downloading" as message, even with action error above:
https://pastebin.ubuntu.com/p/rrSRH5ngrh/

[Frode Nordahl (fnordahl)]

There is no call the charm make that could provide the action output provided above, would you be able to perform some troubleshooting and provide more information about environment that could shed light on why "All snaps up to date." and "lxc" would be outputs from any of the commands the charm run on the unit?

[Pedro Guimarães (pguimaraes)]

I just saw it again:

$ juju run-action --wait octavia-diskimage-retrofit/leader retrofit-image
unit-octavia-diskimage-retrofit-0:
  UnitId: octavia-diskimage-retrofit/0
  id: "195"
  message: '''NoneType'' object is not iterable'
  results:
    Stderr: |
      All snaps up to date.
    Stdout: |
      lxc
  status: failed
  timing:
    completed: 2020-02-27 21:51:34 +0000 UTC
    enqueued: 2020-02-27 21:51:27 +0000 UTC
    started: 2020-02-27 21:51:29 +0000 UTC
$ juju run-action --wait octavia-diskimage-retrofit/leader retrofit-image

[Pedro Guimarães (pguimaraes)]

It is also on the logs, seems this is coming from snap layer:

2020-02-27 07:43:46 DEBUG juju-log Running _assess_status()
2020-02-27 07:45:30 INFO juju-log Initializing Snap Layer
2020-02-27 07:45:30 DEBUG retrofit-image lxc
2020-02-27 07:45:31 DEBUG retrofit-image All snaps up to date.
2020-02-27 07:45:31 DEBUG juju-log Running action "retrofit-image"
2020-02-27 07:45:31 INFO juju-log DEPRECATION WARNING: Function action_get is being removed : moved to function_get()
2020-02-27 07:45:34 ERROR juju-log action "retrofit-image" failed: "'NoneType' object is not iterable"
2020-02-27 07:45:34 INFO juju-log DEPRECATION WARNING: Function action_fail is being removed : moved to function_fail()
2020-02-27 07:47:59 INFO juju-log Reactive main running for hook update-status

I can see "All snaps up to date." on each hook that happens. Probably this is due to snap layer.

[Frode Nordahl (fnordahl)]

We are unable to reproduce the issue, it does not occur in our CI environment. More detail about the environment would be helpful.

[Pedro Guimarães (pguimaraes)]

Hi fnordahl, I am seeing other issues as well.
I added the details on my environment to this bug: https://bugs.launchpad.net/charm-octavia/+bug/1865116

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/710435

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/710435
Committed: https://git.openstack.org/cgit/openstack/charm-octavia-diskimage-retrofit/commit/?id=3bbafb0f71c8860fe9b0b400ada92aee27d7ff38
Submitter: Zuul
Branch: master

commit 3bbafb0f71c8860fe9b0b400ada92aee27d7ff38
Author: Frode Nordahl <email address hidden>
Date: Fri Feb 28 12:11:02 2020 +0100

    Log traceback on action failure

    The information logged by the charm is insuficcient in the event
    of an action failure.

    Change-Id: Icb1ab1c2aead273234996227eee0b829947de27d
    Related-Bug: #1864971