iRODS 4.2.3 delayed rule execution only accepting PLUSET in seconds. Not in minutes or hours.

[Maarten Coonen]

Hello all, 

I'm playing around with iRODS 4.2.3 and noticed some changed behavior in the execution of delayed rules compared to iRODS 4.1.10

In 4.1.10, we could just write any of the examples below and it would just work fine. 

delay("<PLUSET>1h</PLUSET>") {
    # Do something
}

delay("<PLUSET>5m</PLUSET>") {
    # Do something
}

delay("<PLUSET>300s</PLUSET>") {
    # Do something
}

However, in iRODS 4.2.3 it seems that only PLUSET defined in seconds is accepted. When entered in minutes or hours, the delay is scheduled for 1 second after submitting to the delayed queue.

To illustrate this, I wrote a small test rule (source code on GitHub) which gives the following output when called via irule -F :

PLUSET 1h is scheduled in 1 second (= INCORRECT)

irods@irods:/rules/tests$ irule -F delayedExecTest.r "*pluset='1h'"

Current time is 2018-08-09:14:02:58. Adding to queue with delay of 1h

irods@irods:/rules/tests$ iqstat -al

Pending rule-executions

id: 10231

name:

        # Write delayed rodsLog message

        msiWriteRodsLog("This message should appear *pluset after *strtime", 0);

rei_file_path: /var/lib/irods/config/packedRei/rei.rods.2052242976

user_name: rods

address:

time: 1533816179 : 2018-08-09.14:02:59

frequency:

priority:

estimated_exe_time:

notification_addr:

last_exe_time:

exec_status:



### output in rodsLog:

Aug 09 14:03:26 irods /var/lib/irods/log/rodsLog.2018.08.06:  Aug  9 14:03:26 pid:2245 NOTICE: msiWriteRodsLog message: This message should appear 1h after 2018-08-09:14:02:58

Aug 09 14:03:34 irods /var/lib/irods/log/reLog.2018.08.06:  NOTICE: postProcRunRuleExec: exec of 10231 done

PLUSET 5m is scheduled in 1 second (= INCORRECT)

irods@irods:/rules/tests$ irule -F delayedExecTest.r "*pluset='5m'"

Current time is 2018-08-09:14:03:28. Adding to queue with delay of 5m

irods@irods:/rules/tests$ iqstat -al

Pending rule-executions

id: 10232

name:

        # Write delayed rodsLog message

        msiWriteRodsLog("This message should appear *pluset after *strtime", 0);

rei_file_path: /var/lib/irods/config/packedRei/rei.rods.3577188242

user_name: rods

address:

time: 1533816213 : 2018-08-09.14:03:33

frequency:

priority:

estimated_exe_time:

notification_addr:

last_exe_time:

exec_status:

### output in rodsLog:

Aug 09 14:03:56 irods /var/lib/irods/log/rodsLog.2018.08.06:  Aug  9 14:03:56 pid:2258 NOTICE: msiWriteRodsLog message: This message should appear 5m after 2018-08-09:14:03:28

Aug 09 14:04:00 irods /var/lib/irods/log/reLog.2018.08.06:  NOTICE: postProcRunRuleExec: exec of 10232 done

PLUSET 300s is scheduled in 5 minutes (= CORRECT)

irods@irods:/rules/tests$ irule -F delayedExecTest.r "*pluset='300s'"

Current time is 2018-08-09:14:04:01. Adding to queue with delay of 300s

irods@irods:/rules/tests$ iqstat -al

Pending rule-executions

id: 10233

name:

        # Write delayed rodsLog message

        msiWriteRodsLog("This message should appear *pluset after *strtime", 0);

rei_file_path: /var/lib/irods/config/packedRei/rei.rods.2655924912

user_name: rods

address:

time: 1533816541 : 2018-08-09.14:09:01

frequency:

priority:

estimated_exe_time:

notification_addr:

last_exe_time:

exec_status:


### output in rodsLog:

Aug 09 14:09:28 irods /var/lib/irods/log/rodsLog.2018.08.06:  Aug  9 14:09:28 pid:2335 NOTICE: msiWriteRodsLog message: This message should appear 300s after 2018-08-09:14:04:01

Aug 09 14:09:35 irods /var/lib/irods/log/reLog.2018.08.06:  NOTICE: postProcRunRuleExec: exec of 10233 done

My question

Is this indeed changed functionality in iRODS 4.2.3 and if so, could you update the documentation at https://docs.irods.org/4.2.3/plugins/pluggable_rule_engine/#delay-execution ?

Best regards,

Maarten Coonen

[Terrell Russell]

From your three examples... It looks like all units are now discarded and the value is treated as seconds.

1h ... 14:02:58 ... 14:02:59
5m ... 14:03:28 ... 14:03:33
300s ... 14:04:01 ... 14:09:01

I don't remember this being intentional, but we'll definitely update the documentation.

And the code appears very similar to 4.1.x...

  https://github.com/irods/irods/blob/4-2-stable/lib/core/src/rcMisc.cpp#L1768

Will investigate a bit more, I've created an issue:

  https://github.com/irods/irods/issues/4055  

Thanks,

Terrell

--
--
"iRODS: the Integrated Rule-Oriented Data-management System; A community driven, open source, data grid software solution" https://www.irods.org
 
iROD-Chat: http://groups.google.com/group/iROD-Chat

---
You received this message because you are subscribed to the Google Groups "iRODS-Chat" group.
To unsubscribe from this group and stop receiving emails from it, send an email to irod-chat+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Maarten Coonen]

Thanks for the fast response Terrell.

I'm glad to see that you could reproduce it.

I subscribed to the GitHub issue to receive notifications. In the meantime, we'll just convert all delays in our ruleset to seconds.

Best regards,

Maarten

Op donderdag 9 augustus 2018 20:40:59 UTC+2 schreef Terrell Russell:

To unsubscribe from this group and stop receiving emails from it, send an email to irod-chat+...@googlegroups.com.