SSA failure during perform_metadata_scan

[spicoli9000]

Error with SSA running docker versions: manageiq/manageiq:jansa-3, latest-jansa, latest-kasparov.
SSA worked on ivanchuk-8

Logs from testing with latest-jansa:
{"@timestamp":"2021-03-08T19:42:22.571355 ","hostname":"a2569443fbda","pid":3970,"tid":"2ac3751af94c","level":"debug","message":"Q-task_id([job_dispatcher]) MIQ(MiqServer#scan_metadata) ansible-vm3 (ManageIQ::Providers::Azure::CloudManager::Vm)"}
{"@timestamp":"2021-03-08T19:42:23.140106 ","hostname":"a2569443fbda","pid":3970,"tid":"2ac3751af94c","level":"debug","message":"Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Vm#perform_metadata_scan) jstdebug2: in perform_meta
data_scan"}
{"@timestamp":"2021-03-08T19:42:23.140337 ","hostname":"a2569443fbda","pid":3970,"tid":"2ac3751af94c","level":"debug","message":"Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Vm#perform_metadata_scan) name: ansible-vm3 (templat
e = false)"}
{"@timestamp":"2021-03-08T19:42:23.140452 ","hostname":"a2569443fbda","pid":3970,"tid":"2ac3751af94c","level":"debug","message":"Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Vm#perform_metadata_scan) jstdebug2: set vm_args res
ource_group.name"}
{"@timestamp":"2021-03-08T19:42:23.179371 ","hostname":"a2569443fbda","pid":3970,"tid":"2ac3751af94c","level":"debug","message":"Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Vm#perform_metadata_scan) jstdebug2: set vm_args ost.scanData ost: #\u003cOpenStruct args=["eastus", {"ems"=\u003e{"ems"=\u003e{:hostname=\u003enil, :ipaddress=\u003enil, :username=\u003e"4f7b1e0f-8d60-4c7c-8978-8e4c62fa7d77", :password=\u003e"v2:{5yNsUngLLdXAahqvhCCQa6I/6Bp9s7Ln7iPOJApeyx/FHbBsdEc5K4euUQJJRfBtOSAb6smsj9R62ecNEHmIUOW+BLfXPu/riflLqT25VWI=}", :class_name=\u003e"ManageIQ::Providers::Azure::CloudManager"}, "connect_to"=\u003e"host"}, "vmScanProfiles"=\u003e[]}], method_name="scan_metadata", vm_guid="7ddea001-3b3b-4c10-a8f9-cd60c8d98542", category="vmconfig,accounts,software,services,system", taskid="4edcda4f-b853-47f0-91ce-b7987fab5c0a", target_id=3, target_type="VmOrTemplate", scanData={"ems"=\u003e{"ems"=\u003e{:hostname=\u003enil, :ipaddress=\u003enil, :username=\u003e"4f7b1e0f-8d60-4c7c-8978-8e4c62fa7d77", :password=\u003e"v2:{5yNsUngLLdXAahqvhCCQa6I/6Bp9s7Ln7iPOJApeyx/FHbBsdEc5K4euUQJJRfBtOSAb6smsj9R62ecNEHmIUOW+BLfXPu/riflLqT25VWI=}", :class_name=\u003e"ManageIQ::Providers::Azure::CloudManager"}, "connect_to"=\u003e"host"}, "vmScanProfiles"=\u003e[]}, jobid=9, config=#\u003cOpenStruct vmdb=true, forceFleeceDefault=true, capabilities={:vixDisk=\u003efalse}\u003e\u003e"}
{"@timestamp":"2021-03-08T19:42:23.180329 ","hostname":"a2569443fbda","pid":3970,"tid":"2ac3751af94c","level":"err","message":"Q-task_id([job_dispatcher]) MIQ(MiqServer#scan_metadata) undefined method '[]' for nil:NilClass"}

Added debug statements to:
/opt/manageiq/manageiq-gemset/bundler/gems/manageiq-providers-azure-e7914f85e845/app/models/manageiq/providers/azure/cloud_manager/vm_or_template_shared/scanning.rb

def perform_metadata_scan(ost)
    require 'MiqVm/miq_azure_vm'

    vm_args = { :name => name }
    _log.debug("jstdebug2: in perform_metadata_scan")
    _log.debug("name: #{name} (template = #{template})")
    if template
      if managed_image?
        vm_args[:resource_group] = managed_resource_group
        vm_args[:managed_image]  = managed_image_disk_name
      elsif blob_uri
        vm_args[:image_uri] = blob_uri
      else
        vm_args[:image_uri] = uid_ems
      end
    else
      _log.debug("jstdebug2: set vm_args resource_group.name")
      vm_args[:resource_group] = resource_group.name
      #vm_args[:resource_group] = "myapp-rg"
      _log.debug("jstdebug2: set vm_args ost.scanData ost: #{ost}")
      vm_args[:snapshot] = ost.scanData["snapshot"]["name"]
      _log.debug("jstdebug2: vm_args = #{vm_args}")
    end
    _log.debug("jstdebug2: set ost.scantime")
    ost.scanTime = Time.now.utc unless ost.scanTime
    _log.debug("jstdebug2: set armrest")
    armrest      = ext_management_system.connect

seems to fail on:
vm_args[:snapshot] = ost.scanData["snapshot"]["name"]
because I never see:
_log.debug("jstdebug2: vm_args = #{vm_args}")

Note: the Azure snapshot gets created but fails while scanning.

ost object in the log:
{"@timestamp":"2021-03-08T19:42:23.179371 ","hostname":"a2569443fbda","pid":3970,"tid":"2ac3751af94c","level":"debug","message":"Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Vm#perform_metadata_scan) jstdebug2: set vm_args ost.scanData ost: #\u003cOpenStruct args=["eastus", {"ems"=\u003e{"ems"=\u003e{:hostname=\u003enil, :ipaddress=\u003enil, :username=\u003e"4f7b1e0f-8d60-4c7c-8978-8e4c62fa7d77", :password=\u003e"v2:{5yNsUngLLdXAahqvhCCQa6I/6Bp9s7Ln7iPOJApeyx/FHbBsdEc5K4euUQJJRfBtOSAb6smsj9R62ecNEHmIUOW+BLfXPu/riflLqT25VWI=}", :class_name=\u003e"ManageIQ::Providers::Azure::CloudManager"}, "connect_to"=\u003e"host"}, "vmScanProfiles"=\u003e[]}], method_name="scan_metadata", vm_guid="7ddea001-3b3b-4c10-a8f9-cd60c8d98542", category="vmconfig,accounts,software,services,system", taskid="4edcda4f-b853-47f0-91ce-b7987fab5c0a", target_id=3, target_type="VmOrTemplate", scanData={"ems"=\u003e{"ems"=\u003e{:hostname=\u003enil, :ipaddress=\u003enil, :username=\u003e"4f7b1e0f-8d60-4c7c-8978-8e4c62fa7d77", :password=\u003e"v2:{5yNsUngLLdXAahqvhCCQa6I/6Bp9s7Ln7iPOJApeyx/FHbBsdEc5K4euUQJJRfBtOSAb6smsj9R62ecNEHmIUOW+BLfXPu/riflLqT25VWI=}", :class_name=\u003e"ManageIQ::Providers::Azure::CloudManager"}, "connect_to"=\u003e"host"}, "vmScanProfiles"=\u003e[]}, jobid=9, config=#\u003cOpenStruct vmdb=true, forceFleeceDefault=true, capabilities={:vixDisk=\u003efalse}\u003e\u003e"}

[spicoli9000]

From what I can tell, the snapshot field in the ost structure being passed to def perform_metadata_scan(ost) in azure/cloud_manager/vm_or_template_shared/scanning.rb is not being set.
In my limited testing, create_scan_args is done before create_snapshot and the snapshot name is not getting set in the scan args (ost).

Logs:
[----] D, [2021-03-10T14:40:26.944153 #5073:2b01e14e5968] DEBUG -- : Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Scanning::Job#create_scan_args) jstdebug: create_scan_args, scan_args: [ {"ems"=>{"ems"=>{:hostname=>nil, :ipaddress=>nil, :username=>"4f7b1e0f-8d60-4c7c-8978-8e4c62fa7d77", :password=>"v2:{HQD4wX+7wtMGUqEF2jkl8eiVoVQrPbLUhKdYsQE0wCcusKl4HYfUTB0IQC/hg+urL9KL18OdFOX74ZnExhwZN2urZ8DhdxB9TbIH5/wckUI=}", :class_name=>"ManageIQ::Providers::Azure::CloudManager"}, "connect_to"=>"host"}} ]
{"@timestamp":"2021-03-10T14:40:26.944111 ","hostname":"3eccff4aa158","pid":5073,"tid":"2b01e14e5968","level":"debug","message":"Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Scanning::Job#create_scan_args) jstdebug: create_scan_args, scan_args: [ {"ems"=>{"ems"=>{:hostname=>nil, :ipaddress=>nil, :username=>"4f7b1e0f-8d60-4c7c-8978-8e4c62fa7d77", :password=>"v2:{HQD4wX+7wtMGUqEF2jkl8eiVoVQrPbLUhKdYsQE0wCcusKl4HYfUTB0IQC/hg+urL9KL18OdFOX74ZnExhwZN2urZ8DhdxB9TbIH5/wckUI=}", :class_name=>"ManageIQ::Providers::Azure::CloudManager"}, "connect_to"=>"host"}} ]"}
{"@timestamp":"2021-03-10T14:40:26.962066 ","hostname":"3eccff4aa158","pid":5073,"tid":"2b01e14e5968","level":"debug","message":"Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Scanning::Job#call_scan) jstdebug: call_scan, scan_args: [ {"ems"=>{"ems"=>{:hostname=>nil, :ipaddress=>nil, :username=>"4f7b1e0f-8d60-4c7c-8978-8e4c62fa7d77", :password=>"v2:{HQD4wX+7wtMGUqEF2jkl8eiVoVQrPbLUhKdYsQE0wCcusKl4HYfUTB0IQC/hg+urL9KL18OdFOX74ZnExhwZN2urZ8DhdxB9TbIH5/wckUI=}", :class_name=>"ManageIQ::Providers::Azure::CloudManager"}, "connect_to"=>"host"}, "vmScanProfiles"=>[]} ]"}
[----] D, [2021-03-10T14:40:26.962151 #5073:2b01e14e5968] DEBUG -- : Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Scanning::Job#call_scan) jstdebug: call_scan, scan_args: [ {"ems"=>{"ems"=>{:hostname=>nil, :ipaddress=>nil, :username=>"4f7b1e0f-8d60-4c7c-8978-8e4c62fa7d77", :password=>"v2:{HQD4wX+7wtMGUqEF2jkl8eiVoVQrPbLUhKdYsQE0wCcusKl4HYfUTB0IQC/hg+urL9KL18OdFOX74ZnExhwZN2urZ8DhdxB9TbIH5/wckUI=}", :class_name=>"ManageIQ::Providers::Azure::CloudManager"}, "connect_to"=>"host"}, "vmScanProfiles"=>[]} ]
{"@timestamp":"2021-03-10T14:40:27.002620 ","hostname":"3eccff4aa158","pid":5073,"tid":"2b01e14e5968","level":"debug","message":"Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Scanning::Job#call_snapshot_create) jstdebug: call_snapshot_create, after create_snapshot, snapshot_mor: [ansible-vm3_SSA_SNAPSHOT]"}
[----] D, [2021-03-10T14:40:27.002691 #5073:2b01e14e5968] DEBUG -- : Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Scanning::Job#call_snapshot_create) jstdebug: call_snapshot_create, after create_snapshot, snapshot_mor: [ansible-vm3_SSA_SNAPSHOT]
[----] D, [2021-03-10T14:40:36.802709 #5077:2ada57dc597c] DEBUG -- : Q-task_id([job_dispatcher]) MIQ(MiqServer#scan_metadata) jstdebug: scan_metadata, ost= [ #<OpenStruct args=["eastus", "---\nems:\n ems:\n :hostname:\n :ipaddress:\n :username: 4f7b1e0f-8d60-4c7c-8978-8e4c62fa7d77\n :password: v2:{HQD4wX+7wtMGUqEF2jkl8eiVoVQrPbLUhKdYsQE0wCcusKl4HYfUTB0IQC/hg+urL9KL18OdFOX74ZnExhwZN2urZ8DhdxB9TbIH5/wckUI=}\n :class_name: ManageIQ::Providers::Azure::CloudManager\n connect_to: host\nvmScanProfiles: []\n"], method_name="scan_metadata", vm_guid="825e1058-cbf2-430f-83ec-134e1f76a1f7", category="vmconfig,accounts,software,services,system", taskid="98b6538c-a192-43f8-b84f-3c85d7a35439", target_id=3, target_type="VmOrTemplate"> ]
[----] D, [2021-03-10T14:40:39.649749 #5077:2ada57dc597c] DEBUG -- : Q-task_id([job_dispatcher]) MIQ(MiqServer#scan_metadata) jstdebug: scan_metadata, ost.scanData= [ {"ems"=>{"ems"=>{:hostname=>nil, :ipaddress=>nil, :username=>"4f7b1e0f-8d60-4c7c-8978-8e4c62fa7d77", :password=>"v2:{HQD4wX+7wtMGUqEF2jkl8eiVoVQrPbLUhKdYsQE0wCcusKl4HYfUTB0IQC/hg+urL9KL18OdFOX74ZnExhwZN2urZ8DhdxB9TbIH5/wckUI=}", :class_name=>"ManageIQ::Providers::Azure::CloudManager"}, "connect_to"=>"host"}, "vmScanProfiles"=>[]} ]
[----] D, [2021-03-10T14:40:40.104632 #5077:2ada57dc597c] DEBUG -- : Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Vm#perform_metadata_scan) jstdebug: set vm_args
[----] D, [2021-03-10T14:40:40.142899 #5077:2ada57dc597c] DEBUG -- : Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Azure::CloudManager::Vm#perform_metadata_scan) jstdebug: ost = [ #<OpenStruct args=["eastus", {"ems"=>{"ems"=>{:hostname=>nil, :ipaddress=>nil, :username=>"4f7b1e0f-8d60-4c7c-8978-8e4c62fa7d77", :password=>"v2:{HQD4wX+7wtMGUqEF2jkl8eiVoVQrPbLUhKdYsQE0wCcusKl4HYfUTB0IQC/hg+urL9KL18OdFOX74ZnExhwZN2urZ8DhdxB9TbIH5/wckUI=}", :class_name=>"ManageIQ::Providers::Azure::CloudManager"}, "connect_to"=>"host"}, "vmScanProfiles"=>[]}], method_name="scan_metadata", vm_guid="825e1058-cbf2-430f-83ec-134e1f76a1f7", category="vmconfig,accounts,software,services,system", taskid="98b6538c-a192-43f8-b84f-3c85d7a35439", target_id=3, target_type="VmOrTemplate", scanData={"ems"=>{"ems"=>{:hostname=>nil, :ipaddress=>nil, :username=>"4f7b1e0f-8d60-4c7c-8978-8e4c62fa7d77", :password=>"v2:{HQD4wX+7wtMGUqEF2jkl8eiVoVQrPbLUhKdYsQE0wCcusKl4HYfUTB0IQC/hg+urL9KL18OdFOX74ZnExhwZN2urZ8DhdxB9TbIH5/wckUI=}", :class_name=>"ManageIQ::Providers::Azure::CloudManager"}, "connect_to"=>"host"}, "vmScanProfiles"=>[]}, jobid=7, config=#<OpenStruct vmdb=true, forceFleeceDefault=true, capabilities={:vixDisk=>false}>> ]

[Fryguy]

@chessbyte Could this have been affected by your relatively recent refactoring? I can't remember when that landed, but this issue is present in >= jansa-3, according to the OP.

[miq-bot]

This issue has been automatically marked as stale because it has not been updated for at least 3 months.

If you can still reproduce this issue on the current release or on master, please reply with all of the information you have about it in order to keep the issue open.

Thank you for all your contributions! More information about the ManageIQ triage process can be found in the triage process documentation.