Building a Native Extension - mandatory callback gotcha

[jtara]

There is a "gotcha" with API callbacks that should be pointed-out. Note: at first, I thought this was an issue only with mandatory callbacks. No. It is just an issue with callbacks, period. Note also I noticed when while creating a native extension, but I think it applies more generally to all APIs using the new 4.x API scheme.

If a method that has a callback (and callback was supplied) changes some object properties (perhaps via a propertyMap parameter, etc.), and then, subsequent to return, the caller examines object properties, (with any method other than callback) then the property values returned will be incorrect. They will be the property values before the call to the method.

This is true at least for iOS and when the method is called from a Rhodes controller. It seems the property values will not be read correctly within the controller instance. (Keep in mind that controller instances exist only for a single request/response.)

If you examine properties with a lambda callback, you will find they have correct values. Of course, the callback is called after the controller instance terminates. As well, if you examine the properties in a different controller instance, then they will be correct.

In my own extension, then, I've avoided using a mandatory callback. It is a better design anyway. I am writing an extension for Bonjour service discovery. As services are discovered, you get callbacks. But it is useful, as well, to have no callbacks, and then just come back later and examine an array property with results. So, when possible, it's good design to avoid requiring a mandatory callback, and, at the same time, it solves this asynchronous problem with properties.

I'm not sure if this is "a bug or a feature"!

[jtara]

This is a bug, not a feature, IMO!

Unfortunately, it is not the setting of mandatory vs. optional callback that determines the behavior. It occurs even with optional callback, so long as a callback is provided.

If a callback is given (at least a lambda callback) then property values read immediately after the call will not be correct, unless a callback is used to read the property values.

This should be called-out in the documentation until/unless this is fixed.

[jtara]

With callback. Note that returned properties are incorrect, except for the last case, where I used a callback to retrieve the property values.

Note: the {{logInfo}} stuff gets replaced by calls to RHO::Log prior to build.

  def test_bonjour_browser
    # Note: default service type is '_http._tcp_.', default domain is '.local'
    Rho::BonjourBrowser.start( {serviceType: '_appletv-v2._tcp.', domain: ''}, lambda do |callback_data|
      {{#logInfo}} "got callback from Rho::BonjourBrowser.search callback_data = #{callback_data.inspect}" {{/logInfo}}
    end # lambda
    )
    {{#logInfo}}
      [
        "Rho::BonjourBrowser.serviceType = #{Rho::BonjourBrowser.serviceType.inspect}",
        "Rho::BonjourBrowser.domain = #{Rho::BonjourBrowser.domain.inspect}",
        "Rho::BonjourBrowser.getProperty('serviceType') = #{Rho::BonjourBrowser.getProperty('serviceType').inspect}",
        "Rho::BonjourBrowser.getProperty('domain') = #{Rho::BonjourBrowser.getProperty('domain').inspect}",
        "Rho::BonjourBrowser.getAllProperties = #{Rho::BonjourBrowser.getAllProperties.inspect}",
        "Rho::BonjourBrowser.getProperties(['serviceType', 'domain']) = #{Rho::BonjourBrowser.getProperties(['serviceType', 'domain']).inspect}"
      ]
    {{/logInfo}}
    Rho::BonjourBrowser.getAllProperties( lambda do |p|
      {{#logInfo}}
        "lambda property getter test: #{p.inspect}"
      {{/logInfo}}
    end )
    redirect action: :index, query: {msg: 'searching for services'}
  end

2015-03-27 13:33:43.306 rhorunner[54111:8954673] I 03/27/2015 13:33:43:306 20735000                  APP| RHO serve: /app/Settings/test_bonjour_browser
2015-03-27 13:33:43.307 rhorunner[54111:8954727] Test of NSLog
2015-03-27 13:33:43.307 rhorunner[54111:8954727] I 03/27/2015 13:33:43:307 22745000 BonjourBrowser.m:  29| mProperties[@'serviceType'] ='_http._tcp.' mProperties[@'domain'] = 'local.'
2015-03-27 13:33:43.307 rhorunner[54111:8954673] I 03/27/2015 13:33:43:307 20735000   SettingsController| [test_bonjour_browser](34) Rho::BonjourBrowser.serviceType = "_http._tcp."
2015-03-27 13:33:43.307 rhorunner[54111:8954727] I 03/27/2015 13:33:43:307 22745000 BonjourBrowser.m:  30| propertyMap[@'serviceType'] ='_appletv-v2._tcp.' propertyMap['@domain'] = ''
2015-03-27 13:33:43.307 rhorunner[54111:8954673] I 03/27/2015 13:33:43:307 20735000   SettingsController| Rho::BonjourBrowser.domain = "local."
2015-03-27 13:33:43.307 rhorunner[54111:8954727] I 03/27/2015 13:33:43:307 22745000 BonjourBrowser.m:  35| after merge, mProperties[@'serviceType'] ='_appletv-v2._tcp.' mProperties[@'domain'] = ''
2015-03-27 13:33:43.307 rhorunner[54111:8954673] I 03/27/2015 13:33:43:307 20735000   SettingsController| Rho::BonjourBrowser.getProperty('serviceType') = "_http._tcp."
2015-03-27 13:33:43.308 rhorunner[54111:8954673] I 03/27/2015 13:33:43:307 20735000   SettingsController| Rho::BonjourBrowser.getProperty('domain') = "local."
2015-03-27 13:33:43.308 rhorunner[54111:8954673] I 03/27/2015 13:33:43:308 20735000   SettingsController| Rho::BonjourBrowser.getAllProperties = {"ID"=>"SCN1", "serviceType"=>"_http._tcp.", "domain"=>"local."}
2015-03-27 13:33:43.308 rhorunner[54111:8954673] I 03/27/2015 13:33:43:308 20735000   SettingsController| Rho::BonjourBrowser.getProperties(['serviceType', 'domain']) = {"serviceType"=>"_http._tcp.", "domain"=>"local."}
2015-03-27 13:33:43.308 rhorunner[54111:8954727] I 03/27/2015 13:33:43:308 22745000 BonjourBrowser.m:  69| willSearch
2015-03-27 13:33:43.309 rhorunner[54111:8954644] I 03/27/2015 13:33:43:308 147d5300 BonjourBrowser.m: 118| didFindService 'C260B1C7264781F7' moreComing '0'
2015-03-27 13:33:43.309 rhorunner[54111:8954673] I 03/27/2015 13:33:43:309 20735000           HttpServer| GC Start.
2015-03-27 13:33:43.312 rhorunner[54111:8954673] I 03/27/2015 13:33:43:312 20735000           HttpServer| GC End.
2015-03-27 13:33:43.312 rhorunner[54111:8954673] I 03/27/2015 13:33:43:312 20735000           HttpServer| Process URI: '/system/call_ruby_proc_callback'
2015-03-27 13:33:43.312 rhorunner[54111:8954673] I 03/27/2015 13:33:43:312 20735000                  APP| Params: {"__rho_object"=>{"body"=>"1"}, "rho_callback"=>"1"}
2015-03-27 13:33:43.312 rhorunner[54111:8954673] I 03/27/2015 13:33:43:312 20735000   SettingsController| [block in test_bonjour_browser](30) got callback from Rho::BonjourBrowser.search callback_data = {"searching"=>true, "moreComing"=>false, "event"=>"didFindService", "serviceName"=>"C260B1C7264781F7"}
2015-03-27 13:33:43.313 rhorunner[54111:8954673] I 03/27/2015 13:33:43:312 20735000           HttpServer| Process URI: '/system/call_ruby_proc_callback'
2015-03-27 13:33:43.313 rhorunner[54111:8954673] I 03/27/2015 13:33:43:313 20735000                  APP| Params: {"__rho_object"=>{"body"=>"0"}, "rho_callback"=>"1"}
2015-03-27 13:33:43.313 rhorunner[54111:8954673] I 03/27/2015 13:33:43:313 20735000   SettingsController| [block in test_bonjour_browser](43) lambda property getter test: {"ID"=>"SCN1", "serviceType"=>"_appletv-v2._tcp.", "domain"=>""}
2015-03-27 13:33:43.313 rhorunner[54111:8954673] I 03/27/2015 13:33:43:313 20735000           HttpServer| Process URI: '/system/call_ruby_proc_callback'
2015-03-27 13:33:43.313 rhorunner[54111:8954673] I 03/27/2015 13:33:43:313 20735000                  APP| Params: {"__rho_object"=>{"body"=>"2"}, "rho_callback"=>"1"}
2015-03-27 13:33:43.314 rhorunner[54111:8954673] I 03/27/2015 13:33:43:314 20735000   SettingsController| [block in test_bonjour_browser](30) got callback from Rho::BonjourBrowser.search callback_data = {"searching"=>true, "moreComing"=>false, "event"=>"didFindService", "serviceName"=>"C260B1C7264781F7"}
2015-03-27 13:33:43.316 rhorunner[54111:8954673] I 03/27/2015 13:33:43:316 20735000           HttpServer| Process URI: '/app/Settings'
2015-03-27 13:33:43.316 rhorunner[54111:8954673] I 03/27/2015 13:33:43:316 20735000                  APP| RHO serve: /app/Settings
2015-03-27 13:33:43.316 rhorunner[54111:8954673] I 03/27/2015 13:33:43:316 20735000                  APP| Params: {"msg"=>"searching for services"}
2015-03-27 13:33:43.317 rhorunner[54111:8954673] I 03/27/2015 13:33:43:317 20735000           HttpServer| GC Start.
2015-03-27 13:33:43.321 rhorunner[54111:8954673] I 03/27/2015 13:33:43:321 20735000           HttpServer| GC End.
2015-03-27 13:33:43.326 rhorunner[54111:8954644] I 03/27/2015 13:33:43:326 147d5300       SimpleMainView| WebView shouldStartLoadWithRequest( http://127.0.0.1:8080/app/Settings#/app/Settings/test_bonjour_browser )
2015-03-27 13:33:43.841 rhorunner[54111:8954644] I 03/27/2015 13:33:43:841 147d5300 BonjourBrowser.m: 167| Resolved service 'C260B1C7264781F7' with hostName 'Apple-TV.local.' and port '3689'
2015-03-27 13:33:43.842 rhorunner[54111:8954644] I 03/27/2015 13:33:43:842 147d5300 BonjourBrowser.m: 182| Resolution stopped for service 'C260B1C7264781F7'
2015-03-27 13:33:43.842 rhorunner[54111:8954673] I 03/27/2015 13:33:43:842 20735000           HttpServer| Process URI: '/system/call_ruby_proc_callback'
2015-03-27 13:33:43.843 rhorunner[54111:8954673] I 03/27/2015 13:33:43:843 20735000                  APP| Params: {"__rho_object"=>{"body"=>"2"}, "rho_callback"=>"1"}
2015-03-27 13:33:43.843 rhorunner[54111:8954673] I 03/27/2015 13:33:43:843 20735000   SettingsController| [block in test_bonjour_browser](30) got callback from Rho::BonjourBrowser.search callback_data = {"searching"=>true, "hostName"=>"Apple-TV.local.", "moreComing"=>false, "event"=>"didResolveAddress", "serviceName"=>"C260B1C7264781F7", "port"=>3689}

[jtara]

With no callback, properties are as expected:

  def test_bonjour_browser
    # Note: default service type is '_http._tcp_.', default domain is '.local'
    Rho::BonjourBrowser.start( {serviceType: '_appletv-v2._tcp.', domain: ''} )
    {{#logInfo}}
      [
        "Rho::BonjourBrowser.serviceType = #{Rho::BonjourBrowser.serviceType.inspect}",
        "Rho::BonjourBrowser.domain = #{Rho::BonjourBrowser.domain.inspect}",
        "Rho::BonjourBrowser.getProperty('serviceType') = #{Rho::BonjourBrowser.getProperty('serviceType').inspect}",
        "Rho::BonjourBrowser.getProperty('domain') = #{Rho::BonjourBrowser.getProperty('domain').inspect}",
        "Rho::BonjourBrowser.getAllProperties = #{Rho::BonjourBrowser.getAllProperties.inspect}",
        "Rho::BonjourBrowser.getProperties(['serviceType', 'domain']) = #{Rho::BonjourBrowser.getProperties(['serviceType', 'domain']).inspect}"
      ]
    {{/logInfo}}
    Rho::BonjourBrowser.getAllProperties( lambda do |p|
      {{#logInfo}}
        "lambda property getter test: #{p.inspect}"
      {{/logInfo}}
    end )
    redirect action: :index, query: {msg: 'searching for services'}
  end

2015-03-27 13:43:08.758 rhorunner[54616:8962038] I 03/27/2015 13:43:08:758 21d0d000                  APP| RHO serve: /app/Settings/test_bonjour_browser
2015-03-27 13:43:08.758 rhorunner[54616:8962038] Test of NSLog
2015-03-27 13:43:08.758 rhorunner[54616:8962038] I 03/27/2015 13:43:08:758 21d0d000 BonjourBrowser.m:  29| mProperties[@'serviceType'] ='_http._tcp.' mProperties[@'domain'] = 'local.'
2015-03-27 13:43:08.758 rhorunner[54616:8962038] I 03/27/2015 13:43:08:758 21d0d000 BonjourBrowser.m:  30| propertyMap[@'serviceType'] ='_appletv-v2._tcp.' propertyMap['@domain'] = ''
2015-03-27 13:43:08.759 rhorunner[54616:8962038] I 03/27/2015 13:43:08:759 21d0d000 BonjourBrowser.m:  35| after merge, mProperties[@'serviceType'] ='_appletv-v2._tcp.' mProperties[@'domain'] = ''
2015-03-27 13:43:08.759 rhorunner[54616:8962038] I 03/27/2015 13:43:08:759 21d0d000 BonjourBrowser.m:  69| willSearch
2015-03-27 13:43:08.759 rhorunner[54616:8962019] I 03/27/2015 13:43:08:759 15dad300 BonjourBrowser.m: 118| didFindService 'C260B1C7264781F7' moreComing '0'
2015-03-27 13:43:08.760 rhorunner[54616:8962038] I 03/27/2015 13:43:08:760 21d0d000   SettingsController| [test_bonjour_browser](30) Rho::BonjourBrowser.serviceType = "_appletv-v2._tcp."
2015-03-27 13:43:08.760 rhorunner[54616:8962038] I 03/27/2015 13:43:08:760 21d0d000   SettingsController| Rho::BonjourBrowser.domain = ""
2015-03-27 13:43:08.760 rhorunner[54616:8962038] I 03/27/2015 13:43:08:760 21d0d000   SettingsController| Rho::BonjourBrowser.getProperty('serviceType') = "_appletv-v2._tcp."
2015-03-27 13:43:08.760 rhorunner[54616:8962038] I 03/27/2015 13:43:08:760 21d0d000   SettingsController| Rho::BonjourBrowser.getProperty('domain') = ""
2015-03-27 13:43:08.761 rhorunner[54616:8962038] I 03/27/2015 13:43:08:761 21d0d000   SettingsController| Rho::BonjourBrowser.getAllProperties = {"ID"=>"SCN1", "serviceType"=>"_appletv-v2._tcp.", "domain"=>""}
2015-03-27 13:43:08.761 rhorunner[54616:8962038] I 03/27/2015 13:43:08:761 21d0d000   SettingsController| Rho::BonjourBrowser.getProperties(['serviceType', 'domain']) = {"serviceType"=>"_appletv-v2._tcp.", "domain"=>""}
2015-03-27 13:43:08.761 rhorunner[54616:8962038] I 03/27/2015 13:43:08:761 21d0d000           HttpServer| GC Start.
2015-03-27 13:43:08.764 rhorunner[54616:8962038] I 03/27/2015 13:43:08:764 21d0d000           HttpServer| GC End.
2015-03-27 13:43:08.764 rhorunner[54616:8962038] I 03/27/2015 13:43:08:764 21d0d000           HttpServer| Process URI: '/system/call_ruby_proc_callback'
2015-03-27 13:43:08.764 rhorunner[54616:8962038] I 03/27/2015 13:43:08:764 21d0d000                  APP| Params: {"__rho_object"=>{"body"=>"0"}, "rho_callback"=>"1"}
2015-03-27 13:43:08.764 rhorunner[54616:8962038] I 03/27/2015 13:43:08:764 21d0d000   SettingsController| [block in test_bonjour_browser](39) lambda property getter test: {"ID"=>"SCN1", "serviceType"=>"_appletv-v2._tcp.", "domain"=>""}
2015-03-27 13:43:08.765 rhorunner[54616:8962038] I 03/27/2015 13:43:08:765 21d0d000           HttpServer| Process URI: '/app/Settings'
2015-03-27 13:43:08.765 rhorunner[54616:8962038] I 03/27/2015 13:43:08:765 21d0d000                  APP| RHO serve: /app/Settings
2015-03-27 13:43:08.765 rhorunner[54616:8962038] I 03/27/2015 13:43:08:765 21d0d000                  APP| Params: {"msg"=>"searching for services"}
2015-03-27 13:43:08.766 rhorunner[54616:8962038] I 03/27/2015 13:43:08:766 21d0d000           HttpServer| GC Start.
2015-03-27 13:43:08.768 rhorunner[54616:8962038] I 03/27/2015 13:43:08:768 21d0d000           HttpServer| GC End.
2015-03-27 13:43:08.775 rhorunner[54616:8962019] I 03/27/2015 13:43:08:775 15dad300       SimpleMainView| WebView shouldStartLoadWithRequest( http://127.0.0.1:8080/app/Settings#/app/Settings/test_bonjour_browser )
2015-03-27 13:43:09.392 rhorunner[54616:8962019] I 03/27/2015 13:43:09:392 15dad300 BonjourBrowser.m: 167| Resolved service 'C260B1C7264781F7' with hostName 'Apple-TV.local.' and port '3689'
2015-03-27 13:43:09.392 rhorunner[54616:8962019] I 03/27/2015 13:43:09:392 15dad300 BonjourBrowser.m: 182| Resolution stopped for service 'C260B1C7264781F7'

[jtara]

I guess the documentation advice would be that if you provide a callback to a method, and that method also merges some passed properties into the object properties, then the only reliable way to read the properties immediately after the call is by using the callback method of property retrieval.

[darryncampbell]

If a callback is provided then the call will be asynchronous, if the callback is absent then the method will be called synchronously. The behaviour as described sounds reasonable, if calling asynchronously then the developer should only expect the method to complete after the callback is received. This should definitely be documented however, I thought it was but checking the documentation I don't see any mention of it. @michaelToews , I can provide internal design documentation into how the callback mechanism works if it helps documenting this externally. Thanks. @rognar for visibility