We have setuped 2 program stage notification template to run on program stage completion.
one by email to health worker
one by sms to the patient
Note also that we don’t always have the email or phone number
Apparently dhis2 fails it’s notification process not super well.
If the email is not present, he won’t send the sms, see stacktrace below.
When the email and phone number are present both are sent
Questions
is there a way to configure the notifications ex adding condition is the email/phone is present
is this a feature or a bug ? if a bug is this fixed in another version of dhis2 ?
if it’s a feature, why the hell silently failing (why not adding a note to the event with notification sent/failed)
is it normal the sms is not logged in the SMS Configuration App in the “sent” tab.
Message validation failed: No destination found for delivery channel EMAIL (EmailDeliveryChannelStrategy.java [taskScheduler-6])
* ERROR 2022-06-30T10:58:09,993 Unexpected exception occurred invoking async method: public void org.hisp.dhis.program.notification.ProgramNotificationListener.onEvent(org.hisp.dhis.program.notification.event.ProgramStageCompletionNotificationEvent) (SimpleAsyncUncaughtExceptionHandler.java [taskScheduler-6])
org.hisp.dhis.common.IllegalQueryException: No destination found for delivery channel EMAIL
at org.hisp.dhis.program.message.EmailDeliveryChannelStrategy.validate(EmailDeliveryChannelStrategy.java:100) ~[dhis-service-core-2.36.10.1-SNAPSHOT.jar:?]
at org.hisp.dhis.program.message.EmailDeliveryChannelStrategy.setAttributes(EmailDeliveryChannelStrategy.java:60) ~[dhis-service-core-2.36.10.1-SNAPSHOT.jar:?]
at org.hisp.dhis.program.message.DefaultProgramMessageService.setAttributesBasedOnStrategy(DefaultProgramMessageService.java:457) ~[dhis-service-core-2.36.10.1-SNAPSHOT.jar:?]
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193) ~[?:1.8.0_332]
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175) ~[?:1.8.0_332]
at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1384) ~[?:1.8.0_332]
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482) ~[?:1.8.0_332]
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472) ~[?:1.8.0_332]
at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708) ~[?:1.8.0_332]
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:1.8.0_332]
at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:566) ~[?:1.8.0_332]
at org.hisp.dhis.program.message.DefaultProgramMessageService.sendMessages(DefaultProgramMessageService.java:244) ~[dhis-service-core-2.36.10.1-SNAPSHOT.jar:?]
at sun.reflect.GeneratedMethodAccessor2930.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_332]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_332]
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344) ~[spring-aop-5.2.15.RELEASE.jar:5.2.15.RELEASE]
So… now I found a program rule with a wrong expression causing the evaluation to halt or something.
I fixed the expression… restarted a registration, now the mails is skipped or is sent.
The only problem it’s sent way too early. The event is not event yet filled with the important info in it.
is there an expression to verify the status of the event ?
or in last resort I need to check all the (mandatory) fields ?
I want to ask you when the email and phone number are present both are sent. In this case, do you have SMS and EMAIL both selected in one single program stage notification or is it that you have two notifications one for SMS and the other for EMAIL?
Since I moved the email to the programRules triggered instead of “onComplete”.
I see stacktraces like this one below. The stage is in repeatable and I would have assumed that it will redo the notification. From what I understand dhis2 is supposed to check if he already sent a mail notification. the unique id referts to the one via mail (not triggered by program rules)
The behaviour is different from mobile vs dhis2 web capture.
when “complete” via mobiles, nothing gets sent (probably the stacktrace in the logs about email, prevent the sms to be sent)
when “complete” via mail, both are sent (but the mail a bit too earlier)
And now the sms is not sent either.
ID3UZW400eeVqWC6BvVTuZ7j8nKHT7XuM2BWKb1iCxVu4=* WARN 2022-07-11T09:09:22,672 SQL Error: 0, SQLState: 23505 (SqlExceptionHelper.java [taskScheduler-6])
* ERROR 2022-07-11T09:09:22,673 ERROR: duplicate key value violates unique constraint "uk_mcn0op3hsf5ajqg5k4oli4xkc"
Detail: Key (key)=(oR5I4UCVM7ak5E4H1h1ZCA) already exists. (SqlExceptionHelper.java [taskScheduler-6])
* WARN 2022-07-11T09:09:22,677 onPostInsertCommitFailed: org.hibernate.event.spi.PostInsertEvent@64a42b87 (PostInsertAuditListener.java [taskScheduler-6])
* ERROR 2022-07-11T09:09:22,678 Unexpected exception occurred invoking async method: public void org.hisp.dhis.programrule.engine.ProgramRuleEngineListener.onEventCompletion(org.hisp.dhis.programrule.engine.StageCompletionEvaluationEvent) (SimpleAsyncUncaughtExceptionHandler.java [taskScheduler-6])
org.springframework.dao.DataIntegrityViolationException: could not execute statement; SQL [n/a]; constraint [uk_mcn0op3hsf5ajqg5k4oli4xkc]; nested exception is org.hibernate.exception.ConstraintViolationException: could not execute statement
at org.springframework.orm.hibernate5.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:212) ~[spring-orm-5.3.18.jar:5.3.18]
at org.springframework.orm.hibernate5.HibernateTransactionManager.convertHibernateAccessException(HibernateTransactionManager.java:785) ~[spring-orm-5.3.18.jar:5.3.18]
at org.springframework.orm.hibernate5.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:655) ~[spring-orm-5.3.18.jar:5.3.18]
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743) ~[spring-tx-5.3.18.jar:5.3.18]
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711) ~[spring-tx-5.3.18.jar:5.3.18]
at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:654) ~[spring-tx-5.3.18.jar:5.3.18]
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:407) ~[spring-tx-5.3.18.jar:5.3.18]
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.18.jar:5.3.18]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.15.RELEASE.jar:5.2.15.RELEASE]
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.2.15.RELEASE.jar:5.2.15.RELEASE]
at com.sun.proxy.$Proxy306.evaluateEventAndRunEffects(Unknown Source) ~[?:?]
at org.hisp.dhis.programrule.engine.ProgramRuleEngineListener.onEventCompletion(ProgramRuleEngineListener.java:61) ~[dhis-service-program-rule-2.36.10.1-SNAPSHOT.jar:?]
at org.hisp.dhis.programrule.engine.ProgramRuleEngineListener$$FastClassBySpringCGLIB$$de38d172.invoke(<generated>) ~[dhis-service-program-rule-2.36.10.1-SNAPSHOT.jar:?]
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.3.18.jar:5.3.18]
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:779) ~[spring-aop-5.2.15.RELEASE.jar:5.2.15.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.2.15.RELEASE.jar:5.2.15.RELEASE]
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) ~[spring-aop-5.2.15.RELEASE.jar:5.2.15.RELEASE]
at org.springframework.aop.interceptor.AsyncExecutionInterceptor.lambda$invoke$0(AsyncExecutionInterceptor.java:115) ~[spring-aop-5.2.15.RELEASE.jar:5.2.15.RELEASE]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_332]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_332]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_332]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_332]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_332]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_332]
Caused by: org.hibernate.exception.ConstraintViolationException: could not execute statement
at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:109) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:200) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3302) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3829) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:107) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:604) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at java.util.LinkedHashMap.forEach(LinkedHashMap.java:684) ~[?:1.8.0_332]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:345) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:93) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1362) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:453) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3212) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2380) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:447) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.springframework.orm.hibernate5.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:643) ~[spring-orm-5.3.18.jar:5.3.18]
... 21 more
Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "uk_mcn0op3hsf5ajqg5k4oli4xkc"
Detail: Key (key)=(oR5I4UCVM7ak5E4H1h1ZCA) already exists.
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:481) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:401) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164) ~[postgresql-42.2.19.jar:42.2.19]
at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:130) ~[postgresql-42.2.19.jar:42.2.19]
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:1502) ~[c3p0-0.9.5.5.jar:0.9.5.5]
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:197) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3302) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3829) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:107) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:604) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at java.util.LinkedHashMap.forEach(LinkedHashMap.java:684) ~[?:1.8.0_332]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:345) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:93) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1362) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:453) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3212) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2380) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:447) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101) ~[hibernate-core-5.4.28.Final.jar:5.4.28.Final]
at org.springframework.orm.hibernate5.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:643) ~[spring-orm-5.3.18.jar:5.3.18]
... 21 more
* INFO 2022-07-11T09:09:22,687 Invoking message sender: EmailMessageSender$$EnhancerBySpringCGLIB$$66705d71 (DefaultOutboundMessageBatchService.java [taskScheduler-1])
* INFO 2022-07-11T09:09:22,718 Sending email to : mallangba@bluesquarehub.com (EmailMessageSender.java [taskScheduler-1])
* INFO 2022-07-11T09:09:23,006 Email sent using host: smtp.eu.mailgun.org:587 with TLS: true (EmailMessageSender.java [taskScheduler-1])
* INFO 2022-07-11T09:09:23,007 EMAIL batch processed successfully (EmailMessageSender.java [taskScheduler-1])```
Is it possible to make it all in one line rather than separate two lines?
This will require more debugging to find out what the issue really is and what’s causing it. I read around the CoP many posts years ago included the same generic issue and even though the topic was different, it might be that we might need to approach the solution in the same way.
In most of those posts, the issue was related to time zone. If you are using a test instance and willing to test this, could you try to change your time zone back to default or if it’s the default to your location? Install settings, server time zone
Another thing I saw is that the ‘duplicate key’ is in a certain table, but the log above doesn’t show which table to ask you to check.
Al-Gassim,
Thanks for your immediate response. This is about broadcasting email /SMS from DHIS2. My issue is about receiving SMS and using the SMS as a submission to the eIDSR dataset.
it should be 2 lines, it’s not the same content (template) and medium (sms vs mail) and same recipient (dataelement with email vs dataelement phone number) and I had to turn the mail to be optional by specifying triggered by “program rule” where the other is trigger “on event completion”
the duplicate key is probably due to dhis2 not checking “prior” to prepare the sending.
but then you end up with a exception that also stop all the processing and clutter the logs with “false alarms”
I suspect we are the first to make 2 notifications at the same stage (and one of the notification is optional)
To be honest it’s sad that I had to move to program rules for the mail notifications. IMO the notification loop could have just “detected it’s empty, no notification, process next notification template (sms), that’s it”. Here now I have a notification by mail that is triggered too soon.