Step not allowed to create records

ami · August 4, 2021, 7:55am

Hi,

I have a workflow that is triggered on ComposeRecord afterCreate event on module A. In this workflow I’m attempting to create a record for a different module, B. When calling the Function step type Compose record create I get the following message:

workflow 242979608410980356 step 9 execution failed: not allowed to create records"

Any hints on what I’m doing wrong? what should I check?

Thanks

Notes:

The workflow is setup to run as a user which has Administrators role.
The system is started from docker version 2021.3.10

an extract of the log:

e[36mserver      |e[0m 06:15:45.569	e[34mINFOe[0m	http.rest	server/logger.go:43	HTTP request POST /api/automation/workflows/242979608410980356/exec	{"requestID": "e6ab0a61fd88/n6JVzZiB5V-003038", "method": "POST", "path": "/api/automation/workflows/242979608410980356/exec", "size": 6154, "remote": "172.22.0.1"}
e[36mserver      |e[0m 06:15:45.576	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:331	add step to queue	{"workflowID": 242979608410980356, "sessionID": 242982650288209924}
e[36mserver      |e[0m 06:15:45.576	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:357	waiting for status change	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "expecting": [3,4], "interval": "250ms"}
e[36mserver      |e[0m 06:15:45.576	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:410	pulled state from queue	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "stateID": 242982650288275460}
e[36mserver      |e[0m 06:15:45.578	e[35mDEBUGe[0m	workflow.session.exec	types/function.go:91	executed	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "stateID": 242982650288275460, "stepID": 5, "functionRef": "composeRecordsNew", "functionKind": "function", "execTime": "2.716779ms"}
e[36mserver      |e[0m 06:15:45.578	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:641	step executed	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "stateID": 242982650288275460, "stepID": 5, "resultType": "*expr.Vars"}
e[36mserver      |e[0m 06:15:45.578	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:770	next step queued	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "stateID": 242982650288275460, "stepID": 5, "nextStepId": 6}
e[36mserver      |e[0m 06:15:45.578	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:331	add step to queue	{"workflowID": 242979608410980356, "sessionID": 242982650288209924}
e[36mserver      |e[0m 06:15:45.578	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:468	executed	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "stateID": 242982650288275460, "status": "active"}
e[36mserver      |e[0m 06:15:45.578	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:410	pulled state from queue	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "stateID": 242982650288537604}
e[36mserver      |e[0m 06:15:45.579	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:641	step executed	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "stateID": 242982650288537604, "stepID": 6, "resultType": "*expr.Vars"}
e[36mserver      |e[0m 06:15:45.579	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:770	next step queued	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "stateID": 242982650288537604, "stepID": 6, "nextStepId": 9}
e[36mserver      |e[0m 06:15:45.579	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:331	add step to queue	{"workflowID": 242979608410980356, "sessionID": 242982650288209924}
e[36mserver      |e[0m 06:15:45.579	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:468	executed	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "stateID": 242982650288537604, "status": "active"}
e[36mserver      |e[0m 06:15:45.579	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:410	pulled state from queue	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "stateID": 242982650288603140}
e[36mserver      |e[0m 06:15:45.580	e[33mWARNe[0m	workflow.session.exec	types/function.go:93	executed with errors	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "stateID": 242982650288603140, "stepID": 9, "functionRef": "composeRecordsCreate", "functionKind": "function", "execTime": "1.289116ms", "error": "not allowed to create records"}
e[36mserver      |e[0m 06:15:45.580	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:468	executed	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "stateID": 242982650288603140, "status": "failed", "error": "workflow 242979608410980356 step 9 execution failed: not allowed to create records"}
e[36mserver      |e[0m 06:15:45.580	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:500	stopping worker	{"workflowID": 242979608410980356, "sessionID": 242982650288209924}
e[36mserver      |e[0m 06:15:45.593	e[35mDEBUGe[0m	workflow.session	service/session.go:403	session updated	{"sessionID": 242982650288209924, "status": "failed"}
e[36mserver      |e[0m 06:15:45.826	e[35mDEBUGe[0m	workflow.session.exec	wfexec/session.go:370	waiting complete	{"workflowID": 242979608410980356, "sessionID": 242982650288209924, "status": "failed"}
e[36mserver      |e[0m 06:15:45.827	e[34mINFOe[0m	http.rest	server/logger.go:63	HTTP response POST /api/automation/workflows/242979608410980356/exec	{"requestID": "e6ab0a61fd88/n6JVzZiB5V-003038", "method": "POST", "path": "/api/automation/workflows/242979608410980356/exec", "status": 200, "size": 18169, "duration": 0.258296355}

jfortun · August 4, 2021, 8:55am

Hi there !

Does manual creation of records on that module with the user that is set for runAs work?
Are you experiencing this on all composeRecordCreate uses or just this specific one?

Also is there any way you could share the workflow (Export feature in configurator) ?
If not, more information about how step(9) is configured would help.

ami · August 4, 2021, 9:05am

Hi @jfortun

Thanks for your reply:

The user is part of the Administrators. I can manually (UI) manipulate records for that module.
I only tested this usecase, to create a record.
here is the code for the workflow

{
  "workflows": [
    {
      "handle": "ams-new-cyber-to-policy",
      "enabled": true,
      "meta": {
        "name": "AMS: New Cyber to Policy",
        "description": "",
        "visual": null
      },
      "keepSessions": 0,
      "steps": [
        {
          "stepID": "5",
          "kind": "function",
          "ref": "composeRecordsNew",
          "arguments": [
            {
              "target": "module",
              "value": "policy-module",
              "type": "Handle"
            },
            {
              "target": "namespace",
              "value": "ams",
              "type": "Handle"
            }
          ],
          "results": [
            {
              "target": "policy",
              "expr": "record"
            }
          ],
          "meta": {
            "name": "",
            "description": "",
            "visual": {
              "id": "5",
              "parent": "1",
              "value": "create policy",
              "xywh": [
                2712,
                2080,
                200,
                80
              ]
            }
          }
        },
        {
          "stepID": "6",
          "kind": "expressions",
          "ref": "",
          "arguments": [
            {
              "target": "policy.values.StartDate",
              "expr": "record.values.StartDate",
              "type": "DateTime"
            },
            {
              "target": "policy.values.Amount",
              "expr": "record.values.Amount",
              "type": "Float"
            },
            {
              "target": "policy.values.PolicyType",
              "expr": "\"cyber\"",
              "type": "String"
            },
            {
              "target": "policy.values.CyberID",
              "expr": "record.recordID",
              "type": "ID"
            }
          ],
          "results": null,
          "meta": {
            "name": "",
            "description": "",
            "visual": {
              "id": "6",
              "parent": "1",
              "value": "fill policy data",
              "xywh": [
                3120,
                2080,
                200,
                80
              ]
            }
          }
        },
        {
          "stepID": "9",
          "kind": "function",
          "ref": "composeRecordsCreate",
          "arguments": [
            {
              "target": "record",
              "expr": "policy",
              "type": "ComposeRecord"
            }
          ],
          "results": [
            {
              "target": "policy",
              "expr": "record"
            }
          ],
          "meta": {
            "name": "",
            "description": "",
            "visual": {
              "id": "9",
              "parent": "1",
              "value": "save policy",
              "xywh": [
                3440,
                2080,
                200,
                80
              ]
            }
          }
        },
        {
          "stepID": "11",
          "kind": "prompt",
          "ref": "notification",
          "arguments": [
            {
              "target": "title",
              "value": "Policy created",
              "type": "String"
            },
            {
              "target": "message",
              "value": "a  Policy entry was created",
              "type": "String"
            },
            {
              "target": "variant",
              "value": "secondary",
              "type": "String"
            }
          ],
          "results": [],
          "meta": {
            "name": "",
            "description": "",
            "visual": {
              "id": "11",
              "parent": "1",
              "value": "notify user",
              "xywh": [
                2424,
                2304,
                200,
                80
              ]
            }
          }
        },
        {
          "stepID": "14",
          "kind": "termination",
          "ref": "",
          "arguments": null,
          "results": null,
          "meta": {
            "name": "",
            "description": "",
            "visual": {
              "id": "14",
              "parent": "1",
              "value": null,
              "xywh": [
                3016,
                2304,
                200,
                80
              ]
            }
          }
        }
      ],
      "paths": [
        {
          "parentID": "5",
          "childID": "6",
          "meta": {
            "name": "",
            "description": "",
            "visual": {
              "id": "8",
              "parent": "1",
              "points": [],
              "style": "exitX=1;exitY=0.5;exitDx=0;exitDy=0;entryX=0;entryY=0.5;entryDx=0;entryDy=0;",
              "value": null
            }
          }
        },
        {
          "parentID": "6",
          "childID": "9",
          "meta": {
            "name": "",
            "description": "",
            "visual": {
              "id": "10",
              "parent": "1",
              "points": [],
              "style": "exitX=1;exitY=0.5;exitDx=0;exitDy=0;entryX=0;entryY=0.5;entryDx=0;entryDy=0;",
              "value": null
            }
          }
        },
        {
          "parentID": "9",
          "childID": "11",
          "meta": {
            "name": "",
            "description": "",
            "visual": {
              "id": "12",
              "parent": "1",
              "points": [],
              "style": "exitX=1;exitY=0.5;exitDx=0;exitDy=0;entryX=0;entryY=0.5;entryDx=0;entryDy=0;",
              "value": null
            }
          }
        },
        {
          "parentID": "11",
          "childID": "14",
          "meta": {
            "name": "",
            "description": "",
            "visual": {
              "id": "15",
              "parent": "1",
              "points": [],
              "style": "exitX=1;exitY=0.5;exitDx=0;exitDy=0;entryX=0;entryY=0.5;entryDx=0;entryDy=0;",
              "value": null
            }
          }
        }
      ],
      "triggers": [
        {
          "resourceType": "compose:record",
          "eventType": "afterCreate",
          "constraints": [
            {
              "name": "namespace.handle",
              "op": "=",
              "values": [
                "ams"
              ]
            },
            {
              "name": "module.handle",
              "op": "=",
              "values": [
                "cybear-policy-module"
              ]
            }
          ],
          "enabled": true,
          "stepID": "5",
          "meta": {
            "description": "",
            "visual": {
              "edges": [
                {
                  "childID": "5",
                  "meta": {
                    "description": "",
                    "label": "",
                    "visual": {
                      "id": "7",
                      "parent": "1",
                      "points": [],
                      "style": "exitX=1;exitY=0.5;exitDx=0;exitDy=0;entryX=0;entryY=0.5;entryDx=0;entryDy=0;",
                      "value": null
                    }
                  },
                  "parentID": "3"
                }
              ],
              "id": "3",
              "parent": "1",
              "value": "after cybear policy create",
              "xywh": [
                2176,
                2080,
                200,
                80
              ]
            }
          }
        }
      ]
    }
  ]
}```

jfortun · August 4, 2021, 9:20am

All looks good from the configuration side of things.
Will try to reproduce

jfortun · August 4, 2021, 9:43am

Made a namespace/modules based on your specifications. Set the runAs to another admin user, like you do.
The workflow executed correctly and the record was made.

Did you perhaps change any of the default permissions on the policy-module ?
Not sure what else could be causing this.
Also could you try without the runAs set ?

ami · August 4, 2021, 9:57am

Initially I did not want to take a look at permissions at all. I knew my user was Administrator so my guess was it would have all the rights. When I first hit this, I did change the permissions to the policy-module for the Administrators to all allow (see image).

ok, your second suggestion worked.
I removed the Run As entry from the Workflow and ran it in the builder window and … it worked!

what does that mean for the workflow execution? I can see that “created by” to the new record is set to my user (that would be because I’ve run the workflow from the workflow builder UI). I guess the user that is currently logged in got the attribution. What happens If I create the first record from a sink script? That one also has a user to runAs. Hopefully it would inherit from there too. I will test this.
The remaining question would be, what happens if I have a user that is not admin and has no rights to run the workflow? I guess I’ll see

Thank you for the help

jfortun · August 4, 2021, 10:01am

Hmm if it started working after you removed runAs. That would mean the user that was set previously had no permissions. Try with another admin user, if it works then.

If runAs is not set, and the workflow creates a record. It will be created by the user who created the record that triggered the workflow in the first place.
If runAs is set, the createdBy will be set to the user used in runAs

Hopefully this clears some things up

ami · August 4, 2021, 10:14am

When I first created the workflow, I used the user that I was logged on with (the only one present in the system at that time) which is in Administrators. It did not work (the permissions were set on “inherit”). After I’ve changed the permissions to “allow” as in the picture above, it still did not work (even after logout/login).
The only time when it worked was when I took out the runAs.
I just added back the runAs with my user and it fails again.

So to me it looks like the runAs setting for the Workflow somehow gets into a problem when it runs. What kind of checks I can do for this user to understand where the problem might be? (since you mentioned you tried on your side which means that the only difference would be in the user/permissions for that user on my system)

jfortun · August 4, 2021, 10:19am

I would advise that you reset the permission on policy module (for admin role) to inherit.
Then make a new user. Give it the Admin role. And set that user in the runAs option.
This would be the “default” set up, that i have and works for me.

I get your error when the runAs is set to the user that has no permission to create records in policy module

ami · August 4, 2021, 10:20am

I’ve just created another user, again with the Administrators role. Setup the workflow to runAs this new user, still does not work.

ami · August 4, 2021, 10:30am

playing around with adding/removing runAs I got into a different problem when testing workflow from the UI. See the log below.

Notice the status unknown. When this happens, the UI shows that the workflow test started, but it does not seem to finish. There is no Play button on the Trigger element anymore.
Notice it was executed with runAs empty.

server      | 10:26:02.107      DEBUG   workflow.session.exec   wfexec/session.go:331   add step to queue       {"workflowID": 242979608410980356, "sessionID": 243007843844882436}
server      | 10:26:02.107      DEBUG   workflow.session.exec   wfexec/session.go:410   pulled state from queue {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843844947972}
server      | 10:26:02.107      DEBUG   workflow.session.exec   wfexec/session.go:357   waiting for status change       {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "expecting": [3,4], "interval": "250ms"}
server      | 10:26:02.111      DEBUG   workflow.session.exec   types/function.go:91    executed        {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843844947972, "stepID": 5, "functionRef": "composeRecordsNew", "functionKind": "function", "execTime": "3.580385ms"}
server      | 10:26:02.111      DEBUG   workflow.session.exec   wfexec/session.go:641   step executed   {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843844947972, "stepID": 5, "resultType": "*expr.Vars"}
server      | 10:26:02.111      DEBUG   workflow.session.exec   wfexec/session.go:770   next step queued        {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843844947972, "stepID": 5, "nextStepId": 6}
server      | 10:26:02.111      DEBUG   workflow.session.exec   wfexec/session.go:331   add step to queue       {"workflowID": 242979608410980356, "sessionID": 243007843844882436}
server      | 10:26:02.111      DEBUG   workflow.session.exec   wfexec/session.go:468   executed        {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843844947972, "status": "active"}
server      | 10:26:02.111      DEBUG   workflow.session.exec   wfexec/session.go:410   pulled state from queue {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843861594116}
server      | 10:26:02.111      DEBUG   workflow.session.exec   wfexec/session.go:641   step executed   {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843861594116, "stepID": 6, "resultType": "*expr.Vars"}
server      | 10:26:02.111      DEBUG   workflow.session.exec   wfexec/session.go:770   next step queued        {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843861594116, "stepID": 6, "nextStepId": 9}
server      | 10:26:02.111      DEBUG   workflow.session.exec   wfexec/session.go:331   add step to queue       {"workflowID": 242979608410980356, "sessionID": 243007843844882436}
server      | 10:26:02.111      DEBUG   workflow.session.exec   wfexec/session.go:410   pulled state from queue {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843861659652}
server      | 10:26:02.111      DEBUG   workflow.session.exec   wfexec/session.go:468   executed        {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843861594116, "status": "active"}
server      | 10:26:02.121      DEBUG   workflow.session.exec   types/function.go:91    executed        {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843861659652, "stepID": 9, "functionRef": "composeRecordsCreate", "functionKind": "function", "execTime": "10.213175ms"}
server      | 10:26:02.121      DEBUG   workflow.session.exec   wfexec/session.go:641   step executed   {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843861659652, "stepID": 9, "resultType": "*expr.Vars"}
server      | 10:26:02.121      DEBUG   workflow.session.exec   wfexec/session.go:770   next step queued        {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843861659652, "stepID": 9, "nextStepId": 11}
server      | 10:26:02.122      DEBUG   workflow.session.exec   wfexec/session.go:331   add step to queue       {"workflowID": 242979608410980356, "sessionID": 243007843844882436}
server      | 10:26:02.122      DEBUG   workflow.session.exec   wfexec/session.go:468   executed        {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843861659652, "status": "active"}
server      | 10:26:02.122      DEBUG   workflow.session.exec   wfexec/session.go:410   pulled state from queue {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843878371332}
server      | 10:26:02.122      DEBUG   workflow.session.exec   wfexec/session.go:641   step executed   {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843878371332, "stepID": 11, "resultType": "*wfexec.prompted"}
server      | 10:26:02.122      DEBUG   workflow.session.exec   wfexec/session.go:468   executed        {"workflowID": 242979608410980356, "sessionID": 243007843844882436, "stateID": 243007843878371332, "status": "prompted"}
server      | 10:26:02.130      DEBUG   workflow.session        service/session.go:403  session updated {"sessionID": 243007843844882436, "status": "unknown"}

jfortun · August 4, 2021, 10:33am

The test doesn’t finish since you have the prompt step and the prompt needs to be dismissed before the test is completed. If you exclude it from the test it should finish normally

ami · August 4, 2021, 10:35am

there was no prompt in the UI to dismiss or wait for to dissappear.
the prompt type is non blocking

so it seems that another issue with the display of the prompt may be causing this.

jfortun · August 4, 2021, 10:37am

Prompts and in builder testing don’t mix well.
It also doesn’t matter if prompt is blocking or not since workflow still hangs there until it hasn’t been displayed.

If you are testing from builder try to exclude prompts. Otherwise if testing a real scenario, prompts should work fine.

ami · August 4, 2021, 10:48am

thanks for the tip. I’ll avoid prompts in the builder (although they are useful). I’ll try to use debug blocks to figure out stuff.

The problem with prompts is a different issue I guess, I found them erratic sometimes if there are several prompts in a workflow (not in builder). They seem to appear duplicated sometimes or just missing on other occasions.
I could not find a scenario yet, but if I do, I’ll let you know on a different issue.

In conclusion, thank you for the help.
For now I can move on with runAs empty. This works because the context I’m testing with for now is a user that has rights to execute workflows. If however runAs is not empty (and the user still is part of a role that can execute workflows and create records, like administrator) then it seems this does not work in my experience.

jfortun · August 4, 2021, 10:58am

Agreed, prompts need to be improved so that the behaviour is nothing but expected.
Hopefully we can resolve your issue soon