Workflow instances not completing and workflows not advancing: Value too long for column "ERROR_MSG_ VARCHAR(255)": "STRINGDECODE('io.zeebe.cli

I am running into a weird problem where Workflow instances are randomly failing midstream. Random jobs are not being invoked and I am not able to narrow down the root cause. All the appropriate variables are available and in most of the cases where I am experiencing this failure, certain tasks/jobs are not being triggered at all.

This is the list of jobs for this instance:

ServiceTask_15a9gpd 2251799815919545 2251799815919546 payment-service 3 default completed 2019-09-20T02:29:38.606Z
ServiceTask_190tzzn 2251799815919636 2251799815919637 fetching-items-service 0 default failed 2019-09-20T02:29:38.685Z

Or

ServiceTask_15a9gpd 2251799815895211 2251799815895217 payment-service 3 default completed 2019-09-20T02:23:37.294Z
ServiceTask_190tzzn 2251799815895313 2251799815895318 fetching-items-service 3 default completed 2019-09-20T02:23:39.416Z
ServiceTask_1tsa632 2251799815895410 2251799815895412 email-service 3 default completed 2019-09-20T02:23:41.620Z
ServiceTask_1taybaf 2251799815895411 2251799815895413 shipping-service 0 default failed 2019-09-20T02:23:39.611Z

As you can see, it is fairly random which jobs are failing. Any advice on what I should be looking for?

I restarted the docker containers, as I had hundreds of these instances stuck and to see what a fresh install would look like. When I run my workflow again, I am getting random failures. Appears to be with my workflow but cannot pinpoint the problem. Here is a sample of the last 5 instances:

2251799813696775 Active 2019-09-20T03:17:59.341Z
2251799813710800 Active 2019-09-20T03:22:00.468Z
2251799813724581 Active 2019-09-20T03:25:57.262Z
2251799813747871 Completed 2019-09-20T03:33:35.492Z
2251799813750090 Completed 2019-09-20T03:34:10.184Z

When I get these failures, Zeebe monitor also reports these:

zeebe_monitor | java.lang.RuntimeException: Failed to deserialize Protobuf message.
zeebe_monitor | at io.zeebe.hazelcast.connect.java.ZeebeHazelcastMessageListener.onMessage(ZeebeHazelcastMessageListener.java:31) ~[zeebe-hazelcast-connector-0.5.0.jar!/:0.5.0]
zeebe_monitor | at com.hazelcast.client.proxy.ClientTopicProxy$TopicItemHandler.handleTopicEventV10(ClientTopicProxy.java:89) ~[hazelcast-client-3.11.1.jar!/:3.11.1]
zeebe_monitor | at com.hazelcast.client.impl.protocol.codec.TopicAddMessageListenerCodec$AbstractEventHandler.handle(TopicAddMessageListenerCodec.java:147) ~[hazelcast-3.11.1.jar!/:3.11.1]
zeebe_monitor | at com.hazelcast.client.proxy.ClientTopicProxy$TopicItemHandler.handle(ClientTopicProxy.java:77) ~[hazelcast-client-3.11.1.jar!/:3.11.1]
zeebe_monitor | at com.hazelcast.client.spi.impl.listener.AbstractClientListenerService$ClientEventProcessor.run(AbstractClientListenerService.java:368) ~[hazelcast-client-3.11.1.jar!/:3.11.1]
zeebe_monitor | at com.hazelcast.util.executor.StripedExecutor$Worker.process(StripedExecutor.java:226) [hazelcast-3.11.1.jar!/:3.11.1]
zeebe_monitor | at com.hazelcast.util.executor.StripedExecutor$Worker.run(StripedExecutor.java:209) [hazelcast-3.11.1.jar!/:3.11.1]
zeebe_monitor | Caused by: org.springframework.dao.DataIntegrityViolationException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.DataException: could not execute statement
zeebe_monitor | at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:300) ~[spring-orm-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:253) ~[spring-orm-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:536) ~[spring-orm-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:746) ~[spring-tx-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:714) ~[spring-tx-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:533) ~[spring-tx-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:304) ~[spring-tx-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98) ~[spring-tx-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139) ~[spring-tx-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:135) ~[spring-data-jpa-2.1.4.RELEASE.jar!/:2.1.4.RELEASE]
zeebe_monitor | at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93) ~[spring-aop-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:61) ~[spring-data-commons-2.1.4.RELEASE.jar!/:2.1.4.RELEASE]
zeebe_monitor | at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | at com.sun.proxy.$Proxy97.save(Unknown Source) ~[na:na]
zeebe_monitor | at io.zeebe.monitor.zeebe.ZeebeImportService.importIncident(ZeebeImportService.java:207) ~[classes!/:0.15.0]
zeebe_monitor | at io.zeebe.hazelcast.connect.java.ZeebeHazelcastMessageListener.onMessage(ZeebeHazelcastMessageListener.java:29) ~[zeebe-hazelcast-connector-0.5.0.jar!/:0.5.0]
zeebe_monitor | … 6 common frames omitted
zeebe_monitor | Caused by: org.hibernate.exception.DataException: could not execute statement
zeebe_monitor | at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:118) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:178) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3171) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3686) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:90) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:604) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:478) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:356) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1454) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:511) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3283) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2479) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:473) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:178) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:39) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:271) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:98) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:532) ~[spring-orm-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
zeebe_monitor | … 24 common frames omitted
zeebe_monitor | Caused by: org.h2.jdbc.JdbcSQLException: Value too long for column “ERROR_MSG_ VARCHAR(255)”: “STRINGDECODE('io.zeebe.client.api.command.InternalClientException: Failed to deserialize json ‘’{”“item”":"“headphones”","“price… (3243)”; SQL statement:
zeebe_monitor | insert into incident (bpmn_process_id_, created_, element_instance_key_, error_msg_, error_type_, job_key_, resolved_, workflow_instance_key_, workflow_key_, key_) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [22001-197]
zeebe_monitor | at org.h2.engine.SessionRemote.done(SessionRemote.java:623) ~[h2-1.4.197.jar!/:na]
zeebe_monitor | at org.h2.command.CommandRemote.executeUpdate(CommandRemote.java:237) ~[h2-1.4.197.jar!/:na]
zeebe_monitor | at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:199) ~[h2-1.4.197.jar!/:na]
zeebe_monitor | at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:153) ~[h2-1.4.197.jar!/:na]
zeebe_monitor | at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-3.2.0.jar!/:na]
zeebe_monitor | at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-3.2.0.jar!/:na]
zeebe_monitor | at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:175) ~[hibernate-core-5.3.7.Final.jar!/:5.3.7.Final]
zeebe_monitor | … 41 common frames omitted

Hey @klaus.nji,

thanks for this report.

Do you see any exceptions in the Broker log or Client log?
It seems that one of your jobs failed with an exception, could this be the case?
Which Broker and Client version do you use?

Greets
Chris

1 Like

I am using broker version 0.20 and Java client version 0.20 as well. Would you be able to tell me where exactly the broker and client logs are located? I have not added additional log4j2 configuration.

Some additional information:

There was an incident raised in Operate against this workflow instance with the following error:

{

	"activityInstanceId": "2251799813869996",

	"incidentErrorType": "JOB_NO_RETRIES",

	"incidentErrorMessage": "io.zeebe.client.api.command.InternalClientException: Failed to deserialize json '{\"item\":\"headphones\",\"price\":200.0,\"orderId\":892000000,\"payment\":{\"charge\":200.0,\"paymentMethod\":\"VISA\",\"success\":true,\"failureReason\":null,\"accountNumber\":\"1234\"},\"packages\":null,\"shipment\":null,\"orderStatus\":\"PAYMENT-RECEIVED\",\"numberOfItems\":2}' to class 'class com.sailpoint.rss.rss_service.model.OrderCommand'

			at io.zeebe.client.impl.ZeebeObjectMapper.fromJson(ZeebeObjectMapper.java:39)

			at io.zeebe.client.impl.response.ActivatedJobImpl.getVariablesAsType(ActivatedJobImpl.java:132)

			at com.sailpoint.rss.rss_service.services.FetchingService.handle(FetchingService.java:19)

			at io.zeebe.client.impl.worker.JobRunnableFactory.executeJob(JobRunnableFactory.java:44)

			at io.zeebe.client.impl.worker.JobRunnableFactory.lambda$create$0(JobRunnableFactory.java:39)

			at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

			at java.util.concurrent.FutureTask.run(FutureTask.java:266)

			at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)

			at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)

			at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

			at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

			at java.lang.Thread.run(Thread.java:748)

		Caused by: com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException: Unrecognized field \"payment\" (class com.sailpoint.rss.rss_service.model.OrderCommand), not marked as ignorable (8 known properties: \"numberOfItems\", \"item\", \"orderId\", \"shipment\", \"packages\", \"orderProcessingTime\", \"orderProcessed\", \"price\"])

		 at [Source: (String)\"{\"item\":\"headphones\",\"price\":200.0,\"orderId\":892000000,\"payment\":{\"charge\":200.0,\"paymentMethod\":\"VISA\",\"success\":true,\"failureReason\":null,\"accountNumber\":\"1234\"},\"packages\":null,\"shipment\":null,\"orderStatus\":\"PAYMENT-RECEIVED\",\"numberOfItems\":2}\"; line: 1, column: 67] (through reference chain: com.sailpoint.rss.rss_service.model.OrderCommand[\"payment\"])

			at com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException.from(UnrecognizedPropertyException.java:61)

			at com.fasterxml.jackson.databind.DeserializationContext.handleUnknownProperty(DeserializationContext.java:823)

			at com.fasterxml.jackson.databind.deser.std.StdDeserializer.handleUnknownProperty(StdDeserializer.java:1153)

			at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.handleUnknownProperty(BeanDeserializerBase.java:1589)

			at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.handleUnknownVanilla(BeanDeserializerBase.java:1567)

			at com.fasterxml.jackson.databind.deser.BeanDeserializer.vanillaDeserialize(BeanDeserializer.java:294)

			at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:151)

			at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:4014)

			at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3005)

			at io.zeebe.client.impl.ZeebeObjectMapper.fromJson(ZeebeObjectMapper.java:36)

			... 11 more

		",

	"jobId": "2251799813869997",

	"startDate": "20 Sep 2019 11:27:54",

	"endDate": "--"

}

Interestingly enough, I just ran the same workflow a few seconds ago and it ran to completion. My model looks like this:

public class OrderCommand implements Command {

	public String getItem() {
		return item;
	}

	public void setItem(String item) {
		this.item = item;
	}

	public int getNumberOfItems() {
		return numberOfItems;
	}

	public void setNumberOfItems(int numberOfItems) {
		this.numberOfItems = numberOfItems;
	}

	public double getPrice() {
		return price;
	}

	public void setPrice(double price) {
		this.price = price;
	}

	public int getOrderId() {
		return orderId;
	}

	public void setOrderId(int orderId) {
		this.orderId = orderId;
	}

	private int orderId;
	private String item;
	private int numberOfItems;
	private double price;
	
	/*

	public OffsetDateTime getTimeStamp() {
		return timeStamp;
	}

	public void setTimeStamp(OffsetDateTime timeStNamp) {
		this.timeStamp = timeStNamp;
	}

	private OffsetDateTime timeStamp;

*/


	public OrderCommand(){}

	public OrderCommand(String item, int numberOfItems, double price, OffsetDateTime timeStamp) {

		this.item = item;
		this.numberOfItems = numberOfItems;
		this.price = price;
		//this.timeStamp = timeStamp;
		orderId = timeStamp.getNano();
	}

	private String orderStatus;
	//private OffsetDateTime orderProcessingTime;

	public OrderCommand setOrderStatus(String orderStatus) {
		this.orderStatus = orderStatus;
		//this.orderProcessingTime = OffsetDateTime.now();
		return this;
	}
	/*
	public OffsetDateTime getOrderProcessingTime(){
		return this.orderProcessingTime;
	}*/

	public void setOrderProcessingTime(OffsetDateTime orderProcessingTime) {
		//this.orderProcessingTime = orderProcessingTime;
	}

	public String getOrderStatus(){
		return this.orderStatus;
	}

	private String[] packages;
	public void setPackages(String[] packages) {
		this.packages = packages;
	}

	public String[] getPackages(){
		return packages;
	}

	private List<Shipment> shipment;
	public void setShipment(List<Shipment> shipment) {
		this.shipment = shipment;
	}

	public List<Shipment> getShipment(){
		return this.shipment;
	}

	public String toString(){
		return ReflectionToStringBuilder.toString(this);
	}

	private Payment payment;

	public Payment getPayment() {
		return payment;
	}

	public OrderCommand setPayment(Payment payment) {
		this.payment = payment;
		return this;
	}
}

And if I simply retry the job, again in Operate, it looks job completes.

Hey @klaus.nji,

it seems that in your worker code you tried to deserialized the variables into an java object which doesn’t match.

It seems that the payment property wasn’t found.

Unrecognized field \"payment\" (class com.sailpoint.rss.rss_service.model.OrderCommand), not marked as ignorable

Found this in your posted exception message (stacktrace), which was part of the incident.

io.zeebe.client.api.command.InternalClientException: Failed to deserialize json '{\"item\":\"headphones\",\"price\":200.0,\"orderId\":892000000,\"payment\":{\"charge\":200.0,\"paymentMethod\":\"VISA\",\"success\":true,\"failureReason\":null,\"accountNumber\":\"1234\"},\"packages\":null,\"shipment\":null,\"orderStatus\":\"PAYMENT-RECEIVED\",\"numberOfItems\":2}' to class 'class com.sailpoint.rss.rss_service.model.OrderCommand'

   		at io.zeebe.client.impl.ZeebeObjectMapper.fromJson(ZeebeObjectMapper.java:39)

   		at io.zeebe.client.impl.response.ActivatedJobImpl.getVariablesAsType(ActivatedJobImpl.java:132)

   		at com.sailpoint.rss.rss_service.services.FetchingService.handle(FetchingService.java:19)

   		at io.zeebe.client.impl.worker.JobRunnableFactory.executeJob(JobRunnableFactory.java:44)

   		at io.zeebe.client.impl.worker.JobRunnableFactory.lambda$create$0(JobRunnableFactory.java:39)

   		at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

   		at java.util.concurrent.FutureTask.run(FutureTask.java:266)

   		at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)

   		at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)

   		at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

   		at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

   		at java.lang.Thread.run(Thread.java:748)

   	Caused by: com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException: Unrecognized field \"payment\" (class com.sailpoint.rss.rss_service.model.OrderCommand), not marked as ignorable (8 known properties: \"numberOfItems\", \"item\", \"orderId\", \"shipment\", \"packages\", \"orderProcessingTime\", \"orderProcessed\", \"price\"])

   	 at [Source: (String)\"{\"item\":\"headphones\",\"price\":200.0,\"orderId\":892000000,\"payment\":{\"charge\":200.0,\"paymentMethod\":\"VISA\",\"success\":true,\"failureReason\":null,\"accountNumber\":\"1234\"},\"packages\":null,\"shipment\":null,\"orderStatus\":\"PAYMENT-RECEIVED\",\"numberOfItems\":2}\"; line: 1, column: 67] (through reference chain: com.sailpoint.rss.rss_service.model.OrderCommand[\"payment\"])

   		at com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException.from(UnrecognizedPropertyException.java:61)

   		at com.fasterxml.jackson.databind.DeserializationContext.handleUnknownProperty(DeserializationContext.java:823)

   		at com.fasterxml.jackson.databind.deser.std.StdDeserializer.handleUnknownProperty(StdDeserializer.java:1153)

   		at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.handleUnknownProperty(BeanDeserializerBase.java:1589)

   		at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.handleUnknownVanilla(BeanDeserializerBase.java:1567)

   		at com.fasterxml.jackson.databind.deser.BeanDeserializer.vanillaDeserialize(BeanDeserializer.java:294)

   		at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:151)

   		at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:4014)

   		at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3005)

   		at io.zeebe.client.impl.ZeebeObjectMapper.fromJson(ZeebeObjectMapper.java:36)

   		... 11 more

Hope this helps!

Greets
Chris

2 Likes

Yeah… it seems like a JSON to Java mapping problem and it doesn’t seem to be related to Zeebe at all.

@klaus.nji also looking at the code that you shared in the other thread… (Operate has 105 active instances after restarting docker containers)
I can see that you are doing something like

PaymentStatus status = _paymentProcessor.process(order.getPayment());

Which makes me think that the exclusive gateway conditions like:

payment.success==true

Needs to be something like:

order.payment.success==true

And then your code needs to make sure that there is always a payment inside your order for the expressions to work correctly.

HTH

Would be nice to support optional chaining in these expressions, so like: order?.payment?.success==true

Hey guys,

I think this issue is related https://github.com/zeebe-io/zeebe/issues/3043

Greets
Chris

1 Like

@salaboy, thanks for the response and for spotting the error in the gateway condition. Yes, I am passing in an OrderCommandArgs POJO.

Please let not be quick to point this towards the jackson library as I have done a test here. I have run the same OrderCommandArgs through jackson serialization/deserialization via the ZeebeMapper object a million times without a single exception being thrown.

public static void main( String[] args )
    {
        OrderCommandArgs order = new OrderCommandArgs();
        Payment payment = new Payment().setPaymentMethod("Visa") .setAccountNumber("1234");
        order.setPayment(payment);

        ZeebeObjectMapper mapper = new ZeebeObjectMapper();

        String orderStr = null;

        try
        {

            for (int i = 0; i < 1000000; i++) {
                orderStr = mapper.writeValueAsString(order);
                order = mapper.fromJson(orderStr, OrderCommandArgs.class);
            }
        }catch (Exception ex){

            System.out.println(ex);
        }

        System.out.println(order);
        System.out.println( orderStr);
    }

Also, even if this was a jackson serialization issue, catching the exception and re-issuing a message tailored towards the usage here would be more useful as it would point the developer towards the source of the error. Right now, I am going through the POJO to determine what about it is causing the issue and cannot find a problem. If for example my BPMN model has

payment.status

and there is no such object payment in the variable stack, an error message along the lines of

unable to find a payment object in the stack

or something along those lines would be more useful.

Where you able to run my sample project? Even with the changes to the gateway condition, I am running into the same problem.

I have also exposed my sample through this Github repo: https://github.com/knji/zeebe-micronaut-integration/tree/master

Another quick question: Does Zeebe cache the internal workings of a task/worker somewhere? What if I register a task which already exists? Is the old task overwritten as it looks like I am dealing with a very old task! Please note that I am never explicitly closing workers after they have been created… so do not know if this is part of the problem. My usage model goes like this:

final JobWorker emailServiceTask = client.newWorker()
			.jobType("email-service")
			.handler(new EmailService())
			.open();

I just noticed that the deserialization error is going off a different class/package name even though I have changed this. I have cleared the docker volumes, removed the containers and restarted zeebe.

My new OrderCommandArgs model is defined in this package: package micronaut.email.service.models; . Yet somehow the process is failing to deserialize json into this class:

		Caused by: com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException: Unrecognized field \"payment\" (class com.sailpoint.rss.rss_service.model.OrderCommand), not marked as ignorable (8 known properties: \"numberOfItems\", \"item\", \"orderId\", \"shipment\", \"packages\", \"orderProcessingTime\", \"orderProcessed\", \"price\"])		 at [Source: (String)\"{\"item\":\"headphones\",\"price\":200.0,\"orderId\":342000000,\"payment\":{\"charge\":200.0,\"paymentMethod\":\"VISA\",\"success\":false,\"failureReason\":null,\"accountNumber\":\"4567\"},\"packages\":null,\"shipment\":null,\"orderStatus\":null,\"numberOfItems\":2}\"; line: 1, column: 67] (through reference chain: com.sailpoint.rss.rss_service.model.OrderCommand[\"payment\"])			at com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException.from(UnrecognizedPropertyException.java:61)

@klaus.nji I haven’t run the project as that will require time on my side to analyse how to do that and how micronaut works. For now I just looked at the code and try to spot the problems.

The fact that new classes are not recognised sounds like an IDE problem with caching old classes. Are you running your application from your IDE? or are you running a compiled artefact outside of the IDE context?

1 Like

Does Zeebe cache the internal workings of a task/worker somewhere? What if I register a task which already exists?

What you refer to as “register a task”, is “starting a polling client process that subscribes to the task type”. There is no registration. Your client code sits in a loop requesting jobs of that type from the broker using the ActivateJobs gRPC command.

It’s going to do that on a loop until you close the client or quit the program. When jobs of that type are available in response to an ActivateJobs request, the gateway streams them to the client, and your client iterates over them, executing the handler code.

So if the code is old, then as @salaboy points out, it indicates that the client program you are running is not the code you think it is.

1 Like

Guys, thanks for the responses and help. This turned out to be an IDE problem. Somehow IntelliJ is caching old code. When I ran the tasks out of the IDE everything works as expected.

Just one clarification though:

If I submit a POJO to a workflow instance as a variable, in this case, the OrderCommand, my condition is

payment.success== true as opposed to
order.payment.success== true

which was suggested earlier. From my observation, submitting a POJO as a variables results to a flattened variable map.

1 Like

Is your problem solved then? Can you please mark some of the answers as solution?

Problem solved, thank you. IntelliJ caching problem.