Uploaded image for project: 'CFEngine Community'
  1. CFEngine Community
  2. CFE-2706

Normal ordering documentation does not reflect actual behavior of parser on this policy

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open
    • Priority: Medium
    • Resolution: Unresolved
    • Affects Version/s: 3.10.0
    • Fix Version/s: None
    • Component/s: Built-in functions
    • Labels:
      None

      Description

      I know that the theory of convergent promises supposedly means that you don’t have to worry about sequences, but, as you know, the practice is rather the opposite….

      I’ve just run into an instance where the parser behaves in a way differently than documented.

      According to the docs on normal ordering, the pre-eval step only includes vars (and not classes) out of agent bundles.

      Then during the normal eval pass, you have (to give just a subset, in normal order): vars, classes, methods, processes, commands.

      Based on this I would expect, for any bundle written along these lines

      classes: "myclass" expression => fileexists("/some/file");
      vars: myclass:: "myvar" string => execresult("/some/file","noshell");
      classes: myclass:: "someotherclass" expression => strcmp("some string", "$(myvar)");
      methods: someotherclass:: "somebundle";
      processes: "someprocess" if => isvariable("myvar"), restart_class => "dorestart";
      commands: dorestart:: "/do/restart/of/someprocess";
      

      that it would be logically impossible for somebundle to be run after /do/restart/of/someprocess. However, I find that this is not so!

      Evidently the parser notices after myclass is set that it had this vars promise dependent on that class, so it goes ahead and runs /some/file to cache the result for setting myvar later. Now it skips the evaluation of someotherclass because $(myvar) is an unresolved variable, and thus it doesn’t run somebundle (yet), BUT it DOES return context "any" to the isvariable("myvar") call in the "if" attribute of someprocess, so someprocess gets evaluated and /do/restart/of/someprocess gets run. Then on the next pass, verbose output shows 'Computing value of "myvar"', and someotherclass gets set and somebundle is then called.

      So the bug is evidently somewhere between how execresult() calls are handled for a vars promise that is in context for evaluation, but which shouldn't be evaluated until the next pass through the bundle, and how isvariable() calls are handled for a variable which is to be defined (later) by execresult() when isvariable() is called on that variable between the caching of the function call result and the actual computation/assignment of the value of the vars promise.

      ------

      Here is an actual illustration with real code (only slightly modified from the above). Note I tested this on 3.10.0 after discovering it on 3.7.3.

      [root@hub ~]# cat myscript
      #!/bin/sh
      echo some string
      [root@hub ~]# cat test.cf
      bundle agent main {
      classes:
        "myclass" expression => fileexists("/root/myscript");
      vars:
        myclass:: "myvar" string => execresult("/root/myscript","noshell");
      classes:
        myclass:: "someotherclass" expression => strcmp("some string", "$(myvar)");
      methods:
        someotherclass:: "somebundle";
      processes:
        "someprocess" if => isvariable("myvar"), restart_class => "dorestart";
      commands:
        dorestart:: "/bin/echo I should come second";
      }
      
      bundle agent somebundle {
      commands: "/bin/echo I should come first";
      }
      [root@hub ~]# cf-agent -K -f ./test.cf
        notice: Q: ".../bin/echo I sho": I should come second
        notice: Q: ".../bin/echo I sho": I should come first
      [root@hub ~]#
      

      The verbose output from this policy is instructive. I've trimmed off the beginning with the hard classes:

       verbose: END initial soft classes
       verbose: ----------------------------------------------------------------
       verbose:  Preliminary variable/class-context convergence
       verbose: ----------------------------------------------------------------
       verbose: Skipping promise 'someprocess' because 'if'/'ifvarclass' is not defined
       verbose: Setting minimum acceptable TLS version: 1.0
       verbose: ----------------------------------------------------------------
       verbose:  Begin policy/promise evaluation
       verbose: ----------------------------------------------------------------
       verbose: Using bundlesequence =>  {"main"}
       verbose: B: *****************************************************************
       verbose: B: BEGIN bundle main
       verbose: B: *****************************************************************
       verbose: V: .........................................................
       verbose: V: BEGIN variables (pass 1)
       verbose: C: .........................................................
       verbose: C: BEGIN classes / conditions (pass 1)
       verbose: C:     +  Private class: myclass
       verbose: execresult ran '/root/myscript' successfully
       verbose: Caching result for function 'execresult("/root/myscript","noshell")'
       verbose: Observe process table with /bin/ps -eo user,pid,ppid,pgid,pcpu,pmem,vsz,ni,rss:9,nlwp,stime,etime,time,args
       verbose: P: .........................................................
       verbose: P: BEGIN promise 'promise_test_cf_11' of type "processes" (pass 1)
       verbose: P:    Promiser/affected object: 'someprocess'
       verbose: P:    Part of bundle: main
       verbose: P:    Base context class: any
       verbose: P:    "if" class condition: any
       verbose: P:    Stack path: /default/main/processes/'someprocess'[1]
       verbose: Additional promise info: source path './test.cf' at line 11
       verbose: C:     +  Global class: dorestart
       verbose: A: Promise was KEPT
       verbose: P: END processes promise (someprocess)
       verbose: P: .........................................................
       verbose: P: BEGIN promise 'promise_test_cf_13' of type "commands" (pass 1)
       verbose: P:    Promiser/affected object: '/bin/echo I should come second'
       verbose: P:    Part of bundle: main
       verbose: P:    Base context class: dorestart
       verbose: P:    Stack path: /default/main/commands/'/bin/echo I should come second'[1]
       verbose: Promiser string contains a valid executable '/bin/echo' - ok
          info: Executing 'no timeout' ... '/bin/echo I should come second'
       verbose: Setting umask to 77
       verbose: Additional promise info: source path './test.cf' at line 13
       verbose: Finished command related to promiser '/bin/echo I should come second' -- succeeded
        notice: Q: ".../bin/echo I sho": I should come second
          info: Last 1 quoted lines were generated by promiser '/bin/echo I should come second'
          info: Completed execution of '/bin/echo I should come second'
       verbose: A: Promise REPAIRED
       verbose: P: END commands promise (/bin/echo I should come second)
       verbose: V: .........................................................
       verbose: V: BEGIN variables (pass 2)
       verbose: V:     Computing value of 'myvar'
       verbose: C: .........................................................
       verbose: C: BEGIN classes / conditions (pass 2)
       verbose: C:     +  Private class: someotherclass
       verbose: P: .........................................................
       verbose: P: BEGIN promise 'promise_test_cf_9' of type "methods" (pass 2)
       verbose: P:    Promiser/affected object: 'somebundle'
       verbose: P:    Part of bundle: main
       verbose: P:    Base context class: someotherclass
       verbose: P:    Stack path: /default/main/methods/'somebundle'[1]
       verbose: B: *****************************************************************
       verbose: B: BEGIN bundle somebundle
       verbose: B: *****************************************************************
       verbose: P: .........................................................
       verbose: P: BEGIN promise 'promise_test_cf_17' of type "commands" (pass 1)
       verbose: P:    Promiser/affected object: '/bin/echo I should come first'
       verbose: P:    Part of bundle: somebundle
       verbose: P:    Base context class: any
       verbose: P:    Stack path: /default/main/methods/'somebundle'/default/somebundle/commands/'/bin/echo I should come first'[1]
       verbose: Promiser string contains a valid executable '/bin/echo' - ok
          info: Executing 'no timeout' ... '/bin/echo I should come first'
       verbose: Setting umask to 77
       verbose: Additional promise info: source path './test.cf' at line 17
       verbose: Finished command related to promiser '/bin/echo I should come first' -- succeeded
        notice: Q: ".../bin/echo I sho": I should come first
          info: Last 1 quoted lines were generated by promiser '/bin/echo I should come first'
          info: Completed execution of '/bin/echo I should come first'
       verbose: A: Promise REPAIRED
       verbose: P: END commands promise (/bin/echo I should come first)
       verbose: A: ...................................................
       verbose: A: Bundle Accounting Summary for 'somebundle' in namespace default
       verbose: A: Promises kept in 'somebundle' = 0
       verbose: A: Promises not kept in 'somebundle' = 0
       verbose: A: Promises repaired in 'somebundle' = 1
       verbose: A: Aggregate compliance (promises kept/repaired) for bundle 'somebundle' = 100.0%
       verbose: A: ...................................................
       verbose: Additional promise info: source path './test.cf' at line 9
       verbose: Method 'somebundle' invoked repairs
       verbose: B: *****************************************************************
       verbose: B: END bundle somebundle
       verbose: B: *****************************************************************
       verbose: A: Promise REPAIRED
       verbose: P: END methods promise (somebundle)
       verbose: Observe process table with /bin/ps -eo user,pid,ppid,pgid,pcpu,pmem,vsz,ni,rss:9,nlwp,stime,etime,time,args
       verbose: V: .........................................................
       verbose: V: BEGIN variables (pass 3)
       verbose: V:     Computing value of 'myvar'
       verbose: C: .........................................................
       verbose: C: BEGIN classes / conditions (pass 3)
       verbose: Reusing cached process table
       verbose: A: ...................................................
       verbose: A: Bundle Accounting Summary for 'main' in namespace default
       verbose: A: Promises kept in 'main' = 1
       verbose: A: Promises not kept in 'main' = 0
       verbose: A: Promises repaired in 'main' = 3
       verbose: A: Aggregate compliance (promises kept/repaired) for bundle 'main' = 100.0%
       verbose: A: ...................................................
       verbose: B: *****************************************************************
       verbose: B: END bundle main
       verbose: B: *****************************************************************
       verbose: Generate diff state reports for policy './test.cf' SKIPPED
       verbose: No lock purging scheduled
       verbose: Outcome of version (not specified) (agent-0): Promises observed - Total promise compliance: 25% kept, 75% repaired, 0% not kept (out of 4 events). User promise compliance: 25% kept, 75% repaired, 0% not kept (out of 4 events). CFEngine system compliance: 0% kept, 0% repaired, 0% not kept (out of 0 events).
      [root@hub ~]#
      

      Summary: I suspect the bug is either in isvariable(), in execresult(), or in the code that caches execresult() calls and how that interrelates with isvariable() calls.

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              mweilgart Mike Weilgart
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:

                Summary Panel