SMS & Email notification for program stage

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

  1. is there a way to configure the notifications ex adding condition is the email/phone is present
  2. is this a feature or a bug ? if a bug is this fixed in another version of dhis2 ?
  3. if it’s a feature, why the hell silently failing (why not adding a note to the event with notification sent/failed)
  4. 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 trying answering some of my questions

  • question 1 : Programs - DHIS2 Documentation
  • the bad news it’s not used on play, only the child program has notification templates, and they are not conditional.

So I assume, I should

  • create a ProgramVariable : has_email : with the email data element (or phone)
  • create a ProgramRule
    • with expression : d2:hasValue(#{has_email})
    • and action : Send message + pick existing template
  • change the Program stage notification tempate “When to send it ?” to “ProgramRule”

How can I be sure the nofication will only happen when the event is completed ?

so apparently I should use the program variable name directly and not #{}

d2:hasValue('has_email') 

but it’s definitively not working
and I found plenty of issues related to implement my workaround like

if someone can help me it would be great

about my initial problem (one notification blocking the remaining)

There’s a loop that “naively” think it will be ok for all notifications

and then for one of the record an IllegalQueryException is thrown, game over, notification will silently fail.

Note I don’t know if the current behavior is the best.

@Gassim Do you know someone who can help ?

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 ?

Thank you @Stephan_Mestach !

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?

Thanks!

I have 2 lines in the “Program stage notifications” tab

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)

/api/identifiableObjects/Sgv0s5bLglE.json
return something

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])```

Hi @Stephan_Mestach,

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.


@Gerald_Thomas, might this be related to the issue you just posted?

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.

1 Like

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.