Field values disappearing when ordering through custom service dialog

Support
#1

Hello,

I have created a simple custom service dialog with 2 tabs and ~10 fields in total. One of the fields is called “service_name” where the requester can enter the desired name of the service.

The problem is that even if the field has text in it, ocassionally (about once every 5 times) the service provisioning is initiated with an empty value in the “service_name” dialog. So the entered value simply disappears and the provisioning process will fail later on where the value would be used.

Has anyone experienced something similar? Any suggestions on where should I look?

Thanks,
Miklos

#2

HI @Miklos_Balazs may be your field has refreshed by another field check that “autorefresh” checkbox is unchecked for this field.

#3

@igortiunov I’ve already turned off all auto refresh options and dynamic fields, it wasn’t that.

#4

I am provisioning a bundled service through that dialog. The first custom method in the provisioning process is in /Service/Provisioning/StateMachines/ServiceProvision_Template/CatalogBundleInitialization.

I have put a custom method in pre4 there, but the value is already missing at that point, so it’s not some custom method that’s removing that value. It’s either the built-in DialogParser or CatalogBundleInitialization methods, or maybe the web browser itself? I’ll try to check that…

#5

@Miklos_Balazs
For non-compozite service (not a bundle) this work well, I can set service_name and through inspection see it at any stage of provisioning as dialog_service_name options hash key. DialogParser just copy value of dialog_service_name to service_name.

CatalogBundleInitialization state machine have CatalogBundleInitialization relatoinship with CatalogBundleInitialization method. This method have this function:

def override_service_attribute(dialogs_options_hash, attr_name)
  service_attr_name = "service_#{attr_name}".to_sym

  log_and_update_message(:info, "Processing override_attribute for #{service_attr_name}...", true)
  attr_value = dialogs_options_hash.fetch(service_attr_name, nil)
  attr_value = "#{@service.name}-#{Time.now.strftime('%Y%m%d-%H%M%S')}" if attr_name == 'name' && attr_value.nil?

  log_and_update_message(:info, "Setting service attribute: #{attr_name} to: #{attr_value}")
  @service.send("#{attr_name}=", attr_value)

  log_and_update_message(:info, "Processing override_attribute for #{service_attr_name}...Complete", true)
end

May be there the value of service_name is overrided. Try to parse log/evm.log for ‘Processing override_attribute for’ string.

Try to move pre2 to pre3 and at pre2 investigate options hash for service_name and dialog_service_name after DialogParser.

#6

What I did is that I have put my test method in pre1 of the CatalogBundleInitialization state machine, after 4-5 repeated (and successful) service requests, the service_name value was again empty at the last request.

And this time I checked on the browser side too, that the actual value of the input film was posted, so the server has got the value.

Any other suggestions on where to look?

#7

@igortiunov also, the root of the problem is that the service name is empty in the dialog hash itself. It is very strange because there are other fields on the form and those values are always submitted correctly.

Somehow the value of the service_name dialog parameter disappears somewhere. I’m more and more convinced that this is a bug. I have confirmed that the browser sends the value in a POST request, just as all the other values of the form. And then, when the automation engine is processing the request, the options[:dialog][“dialog_service_name”] value of the request is empty.

I will try to add a custom code to /System/Event RequestEvent/Request/request_created instance to print the dialog options hash right after the request gets into AE so we’ll see if this is a backend problem or a problem within the AE.

#8

So, I have modified the /System/Event/RequestEvent/Request/request_created instance to print the service name, and it confirmed that the value of the service_name dialog element is missing at the time the request gets passed to the AE, so this is a bug in the ManageIQ backend.

In production.log I can see that the value got posted from the browser to the backend:

[----] I, [2017-05-25T16:24:28.724777 #3234:12e7f60] INFO – : Processing by CatalogController#dialog_field_changed as JS
[----] I, [2017-05-25T16:24:28.724942 #3234:12e7f60] INFO – : Parameters: {“service_name”=>“csut42”, “id”=>“39000000000003”}

But it got cleared somehow after this point.

#9

Ok, I have noticed a difference between the two cases (when the value is correctly passed vs. when the value is cleared):

The production.log looks like this when it the value is correctly passed on to the AE:

[----] I, [2017-05-25T16:28:24.742730 #3234:12e42ac]  INFO -- : Processing by CatalogController#dialog_field_changed as JS
[----] I, [2017-05-25T16:28:24.742853 #3234:12e42ac]  INFO -- :   Parameters: {"service_name"=>"csut53", "id"=>"39000000000003"}
[----] I, [2017-05-25T16:28:24.881861 #3234:12e42ac]  INFO -- : Completed 200 OK in 139ms (Views: 0.9ms | ActiveRecord: 0.0ms)
[----] I, [2017-05-25T16:28:25.331021 #3234:12e8f00]  INFO -- : Started POST "/catalog/dialog_field_changed/39000000000003?wp_header=header2.jpg" for 127.0.0.1 at 2017-05-25 16:28:25 +0200
[----] I, [2017-05-25T16:28:25.333080 #3234:12e8f00]  INFO -- : Processing by CatalogController#dialog_field_changed as JS
[----] I, [2017-05-25T16:28:25.333233 #3234:12e8f00]  INFO -- :   Parameters: {"wp_header"=>"header2.jpg", "id"=>"39000000000003"}
[----] I, [2017-05-25T16:28:25.464669 #3234:12e8f00]  INFO -- : Completed 200 OK in 131ms (Views: 0.8ms | ActiveRecord: 0.0ms)

However, the value is cleared if the processing of two input changes overlaps in time:

[----] I, [2017-05-25T16:31:36.659017 #3234:12e42ac]  INFO -- : Started POST "/catalog/dialog_field_changed/39000000000003" for 127.0.0.1 at 2017-05-25 16:31:
36 +0200
[----] I, [2017-05-25T16:31:36.662529 #3234:12e42ac]  INFO -- : Processing by CatalogController#dialog_field_changed as JS
[----] I, [2017-05-25T16:31:36.662643 #3234:12e42ac]  INFO -- :   Parameters: {"service_name"=>"csut55", "id"=>"39000000000003"}
[----] I, [2017-05-25T16:31:36.692244 #3234:12e8f00]  INFO -- : Started POST "/catalog/dialog_field_changed/39000000000003" for 127.0.0.1 at 2017-05-25 16:31:
36 +0200
[----] I, [2017-05-25T16:31:36.697534 #3234:12e8f00]  INFO -- : Processing by CatalogController#dialog_field_changed as JS
[----] I, [2017-05-25T16:31:36.697681 #3234:12e8f00]  INFO -- :   Parameters: {"frontend"=>"windows", "authenticity_token"=>"KXBQ/b4TDeSyGYa7NSKlrpaVTp7ptY1i0
Bc2VrTw15m1ueX+73HqVABvGuzphHWXteDO6brDiGj8SZAZZin7ow==", "id"=>"39000000000003"}
[----] I, [2017-05-25T16:31:36.871109 #3234:12e42ac]  INFO -- : Completed 200 OK in 208ms (Views: 1.0ms | ActiveRecord: 0.0ms)
[----] I, [2017-05-25T16:31:36.953501 #3234:12e8f00]  INFO -- : Completed 200 OK in 256ms (Views: 1.1ms | ActiveRecord: 0.0ms)

So this is a bug in how the dialog fields are processed in CatalogController#dialog_field_changed. There is a race condition when two changes arrive simultaneously.

#10

Hi @Miklos_Balazs
What is “two input changes” in your case ?

#11

@igortiunov: I have entered a value in the service name field, and turned a radio button input.
Sometimes when the browser is busy, the POST of the first input change (service name) overlaps with the POST of the second input change (radio button) and that’s when the value gets cleared.

I have repeated this multiple time and then correlation is evident: when there are no overlapping POSTs, the value is there, and when there are overlappin POSTs, the value is missing.

#12

It turns out that this error can be reproduced for any type of service. Maybe the problem is in the radio button? I use a relatively complex service to deploy openstack instances including the auto generation of service_name by userid (user login name) and the user can override this text box. And this work well any time.

#13

The problem happens specifically when the browser sends two dialog_field_changed requests in parallel. This depends on a lot of factors on the client side, especially how fast the client machine is. I presume that the slower the browser on the client is, the more likely it will send two requests in parallel. I will check the code in CatalogController and see if I can make a patch for this.

#14

@Miklos_Balazs Could you find the problem in the CatalogController and were you able to make a patch? We are facing a similar issue in ManageIQ. We are using Fine 3 (september 2017).

#15

I have investigated this issue for a while but at the end I have found that the fix would require a large scale refactoring in how the dialog field changes are handled, and gave up on it as I don’t have enough knowledge on ManageIQ internals…

But in the meantime I have pinpointed the exact cause of the error and have found a workaround: the problem can appear when the user have changed the value of some input field, and then clicks on the submit button immediately. When this happens, two dialog_field_changed requests get generated: one for the input field losing focus, and one for clicking the submit button - and this is where the race condition can be triggered.

The workaround: when modifying the input fields, the user should always click on a white area on the form so that the last changed input field loses focus, and only click on the submit button afterwards. Hope this helps…