Serialized variable not available but in database

[schmke]

I have a process where there are several required form properties, and when creating the process instance I also set a variable which happens to be a Map. This seems to work fine, I see the variable show up in ACT_RU_VARIABLE as a serialized variable and the serialized value is in ACT_GE_BYTEARRAY.

However, I have a subsequent service task where I want to map my variable “record” to a field also named “record”, this is the extension element:

    <activiti:field name="record">
      <activiti:string><![CDATA[${record}]]></activiti:string>
    </activiti:field>

I have other variables mapped to fields exactly the same way that work, but this one fails with:

20180209 15:27:54.028 [ERROR] pool-50-thread-1 | 390:org.activiti.engine | org.activiti.engine.impl.interceptor.CommandContext | Error while closing command context
org.activiti.engine.ActivitiException: Unknown property used in expression: ${record}
at org.activiti.engine.impl.el.JuelExpression.getValue(JuelExpression.java:53)[390:org.activiti.engine:5.23.0]

when I try to get the value on the Expression just like my other fields.

If I instead just try to get the variable on the execution with:

execution.getVariable(“record”)

that returns null.

What am I doing wrong to be able to map or access a serialized variable?

I am using Flowable 5.23.

Thanks.

[joram]

The fact that the .getVariable call returns null is odd. Can you paste the entry in the variable database table? e.g. can you check if the process instance id / execution id is correctly set?

[schmke]

My process instance completed, so I’m looking at ACT_HI_PROCINST and ACT_HI_VARINST, but my PI is 12557 and the row in ACT_HI_PROCINST is:

±------±--------------±--------------±------------------------±------------------------±------------------------±----------±---------------±--------------±------------±---------------------------±---------------±-----------±------+
| ID_ | PROC_INST_ID_ | BUSINESS_KEY_ | PROC_DEF_ID_ | START_TIME_ | END_TIME_ | DURATION_ | START_USER_ID_ | START_ACT_ID_ | END_ACT_ID_ | SUPER_PROCESS_INSTANCE_ID_ | DELETE_REASON_ | TENANT_ID_ | NAME_ |
±------±--------------±--------------±------------------------±------------------------±------------------------±----------±---------------±--------------±------------±---------------------------±---------------±-----------±------+
| 12557 | 12557 | NULL | AddSystemRecord:2:12532 | 2018-02-09 15:40:04.957 | 2018-02-09 15:45:03.729 | 298772 | ngs | startevent1 | mergeEnd | NULL | NULL | | NULL |
±------±--------------±--------------±------------------------±------------------------±------------------------±----------±---------------±--------------±------------±---------------------------±---------------±-----------±------+

I then have seven variables in ACT_HI_VARINST:

±------±--------------±--------------±---------±----------±-------------±-----±--------------±--------±------±---------------±-------±------------------------±------------------------+
| ID_ | PROC_INST_ID_ | EXECUTION_ID_ | TASK_ID_ | NAME_ | VAR_TYPE_ | REV_ | BYTEARRAY_ID_ | DOUBLE_ | LONG_ | TEXT_ | TEXT2_ | CREATE_TIME_ | LAST_UPDATED_TIME_ |
±------±--------------±--------------±---------±----------±-------------±-----±--------------±--------±------±---------------±-------±------------------------±------------------------+
| 12558 | 12557 | 12557 | NULL | initiator | string | 1 | NULL | NULL | NULL | ngs | NULL | 2018-02-09 15:40:04.956 | 2018-02-09 15:45:03.742 |
| 12566 | 12557 | 12557 | NULL | euid | null | 1 | NULL | NULL | NULL | NULL | NULL | 2018-02-09 15:40:04.957 | 2018-02-09 15:45:03.742 |
| 12567 | 12557 | 12557 | NULL | system | string | 1 | NULL | NULL | NULL | SYS_A | NULL | 2018-02-09 15:40:04.957 | 2018-02-09 15:45:03.742 |
| 12568 | 12557 | 12557 | NULL | lid | string | 1 | NULL | NULL | NULL | K1234 | NULL | 2018-02-09 15:40:04.957 | 2018-02-09 15:45:03.742 |
| 12569 | 12557 | 12557 | NULL | appName | string | 1 | NULL | NULL | NULL | Person | NULL | 2018-02-09 15:40:04.957 | 2018-02-09 15:45:03.742 |
| 12570 | 12557 | 12557 | NULL | _summary | string | 1 | NULL | NULL | NULL | My test create | NULL | 2018-02-09 15:40:04.957 | 2018-02-09 15:45:03.742 |
| 12574 | 12557 | 12557 | NULL | record | serializable | 1 | 12575 | NULL | NULL | NULL | NULL | 2018-02-09 15:40:04.993 | 2018-02-09 15:45:03.742 |
±------±--------------±--------------±---------±----------±-------------±-----±--------------±--------±------±---------------±-------±------------------------±------------------------+

The last one being the one in question. The row with ID 12575 in ACT_GE_BYTEARRAY is:

±------±-----±----------------±---------------±--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------±-----------+
| ID_ | REV_ | NAME_ | DEPLOYMENT_ID_ | BYTES_ | GENERATED_ |
±------±-----±----------------±---------------±--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------±-----------+
| 12575 | 1 | hist.var-record | NULL | ?? sr java.util.LinkedHashMap4?N\l?? Z
accessOrderxr java.util.HashMap???`? F
loadFactorI thresholdxp?@ t Personsq ~ ?@ t FirstNamet KevintLastNamet Schmidtx x | NULL |
±------±-----±----------------±---------------±--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------±-----------+

So it looks like everything is in the database correctly, the API is just not finding it.

Anything else to try or look at?

[schmke]

Upon doing more testing, sometimes it works, others it doesn’t. I discovered this by debugging it and then things started working, so I added some logging and just ran it normally and it seems there is a timing issue or race condition and sometimes it will fail on first try but when it retries it succeeds.

The process is extremely simple, Start --> Service Task --> End, so is there something perhaps asynchronous that is persisting the serializable variable that isn’t complete yet when the Service Task executes, but ends up being done on one of the retries and so succeeds?

[schmke]

To further confirm my suspicion, I added a timer event before the service task and with that delay introduced, I have not seen a failure.

The next question is, assuming this is right and serialized variables aren’t necessarily fully persisted before the next step in a process is performed, can this happen anywhere or is it unique to the first step after a start event?

Also, I know I’m using an old version, so is this issue present in the latest release? Is there a solution for my version other than introducing an artificial delay?

Thanks.

[joram]

@schmke

The next question is, assuming this is right and serialized variables aren’t necessarily fully persisted before the next step in a process is performed, can this happen anywhere or is it unique to the first step after a start event?

Good analysis. Serialized variables are indeed not fully persisted until the end of the transaction. They are marked as ‘changed’ and only evaluated at the end, for not impacting performance as serialization is quite heavy. So to be honest, I’m surprised it worked sometimes.

@schmke

Also, I know I’m using an old version, so is this issue present in the latest release? Is there a solution for my version other than introducing an artificial delay?

Not for serialized variables. Regular variables (the ones not stored as bytes) will work properly as they don’t have this delay.

[schmke]

@joram

@schmke

The next question is, assuming this is right and serialized variables aren’t necessarily fully persisted before the next step in a process is performed, can this happen anywhere or is it unique to the first step after a start event?

Good analysis. Serialized variables are indeed not fully persisted until the end of the transaction. They are marked as ‘changed’ and only evaluated at the end, for not impacting performance as serialization is quite heavy. So to be honest, I’m surprised it worked sometimes.

I may have been fiddling with making some steps (a)synchronous and/or it was the step being retried that made it work in some cases.

But if the variable is marked as ‘changed’ it is in memory then, is there any way to access it rather than the variable retrieval hitting the database where the variable has not yet been persisted?

@joram

@schmke

Also, I know I’m using an old version, so is this issue present in the latest release? Is there a solution for my version other than introducing an artificial delay?

Not for serialized variables. Regular variables (the ones not stored as bytes) will work properly as they don’t have this delay.

So is this a bug? Or this is by design? Certainly seems like a bug to me so should an issue be opened?

And given your description, until the bug is fixed, it seems like the only workaround is to introduce a step in the process to complete the transaction so it gets persisted, is that accurate? A timer works, but is there a better technique to accomplish this that doesn’t introduce a delay? I set a timer for 1 second but the default executor appears to be set to check every 10 seconds so that is a longish delay much of the time. I have changed the executor check period to 1 second, but I assume that has drawbacks of it checking a whole lot more often.