Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Uploading data raises a KeyError -1205000 once the logical quota starts monitoring #379

Closed
mstfdkmn opened this issue Jul 28, 2022 · 48 comments

Comments

@mstfdkmn
Copy link

mstfdkmn commented Jul 28, 2022

iRODS server version: 4.2.10
python-irodsclient version: 1.1.4

What did you do?:

Showing here the monitoring result:

[user1@dev-u0137480 ~]$ imeta ls -C /u0137480/home/lt1_d_pilot_003
AVUs defined for collection /u0137480/home/lt1_d_pilot_003:
attribute: irods::logical_quotas::total_number_of_data_objects
value: 5
units:
----
attribute: irods::logical_quotas::total_size_in_bytes
value: 175
units:

Content of the upload script:

import os, os.path
from irods.session import iRODSSession

env_file = os.getenv('IRODS_ENVIRONMENT_FILE', os.path.expanduser('~/.irods/irods_environment.json'))
with iRODSSession(irods_env_file=env_file) as session:

    session.data_objects.put("test.txt", "/u0137480/home/lt1_d_pilot_003/test.txt")

What happened:

The script crashed with KeyError: -1205000.
However the data object in question has been uploaded.

Error:

[user2@dev-u0137480 ~]$ python upload.py
Traceback (most recent call last):
  File "upload.py", line 7, in <module>
    session.data_objects.put("test.txt", "/u0137480/home/lt1_d_pilot_003/test.txt")
  File "/usr/lib/python2.7/site-packages/irods/manager/data_object_manager.py", line 162, in put
    o.write(chunk)
  File "/usr/lib/python2.7/site-packages/irods/data_object.py", line 177, in close
    self.conn.close_file(self.desc, **self.options)
  File "/usr/lib/python2.7/site-packages/irods/connection.py", line 616, in close_file
    self.recv()
  File "/usr/lib/python2.7/site-packages/irods/connection.py", line 132, in recv
    raise get_exception_by_code(msg.int_info, err_msg)
  File "/usr/lib/python2.7/site-packages/irods/exception.py", line 107, in get_exception_by_code
    exc_class = iRODSExceptionMeta.codes[ rounded_code( code ) ]
KeyError: -1205000

What did you expect:

The data object to be uploaded without seeing any error message after running the script.

Other inputs:

  • This only happens for rodsusers. Rodsadmins can upload without an error.
  • iCommands - iput- works normal.
@d-w-moore
Copy link
Collaborator

Did an iput or istream write of the same test file also evoke the error?

@trel
Copy link
Member

trel commented Jul 28, 2022

$ ierror 1205000
irods error: -1205000 RE_RUNTIME_ERROR 

@trel
Copy link
Member

trel commented Jul 28, 2022

Is this the same issue as irods/irods_rule_engine_plugin_logical_quotas#46 ?

That was included/fixed in 4.2.11.0

@mstfdkmn
Copy link
Author

Did an iput or istream write of the same test file also evoke the error?

No, iCommands works fine.

@mstfdkmn
Copy link
Author

mstfdkmn commented Jul 28, 2022

Is this the same issue as irods/irods_rule_engine_plugin_logical_quotas#46 ?

That was included/fixed in 4.2.11.0

This user has the user based permission in addition to the group permission:

[user2@dev-u0137480 ~]$ ils -A
/u0137480/home/lt1_d_pilot_003:
        ACL - user2#u0137480:own   g:lt1_d_pilot_003#u0137480:own

@mstfdkmn
Copy link
Author

mstfdkmn commented Aug 1, 2022

FYI: This has been tested for 4.2.11 (irods and the logical quotas plugin) as well and I am verifying that I come across the same issue. This issue is happening also for the users' home collections even if nothing related to the rodsadmin group permission exists.

permission:

[user1@dev-u0137480-instance1 ~]$ ils -A
/u0137480_instance1/home/user1:
        ACL - user1#u0137480_instance1:own
        Inheritance - Disabled

key error:

[user1@dev-u0137480-instance1 ~]$ python upload.py
Traceback (most recent call last):
  File "upload.py", line 7, in <module>
    session.data_objects.put("test.txt", "/u0137480_instance1/home/user1/test.txt")
  File "/usr/lib/python2.7/site-packages/irods/manager/data_object_manager.py", line 162, in put
    o.write(chunk)
  File "/usr/lib/python2.7/site-packages/irods/data_object.py", line 177, in close
    self.conn.close_file(self.desc, **self.options)
  File "/usr/lib/python2.7/site-packages/irods/connection.py", line 616, in close_file
    self.recv()
  File "/usr/lib/python2.7/site-packages/irods/connection.py", line 132, in recv
    raise get_exception_by_code(msg.int_info, err_msg)
  File "/usr/lib/python2.7/site-packages/irods/exception.py", line 107, in get_exception_by_code
    exc_class = iRODSExceptionMeta.codes[ rounded_code( code ) ]
KeyError: -1205000

@mstfdkmn
Copy link
Author

mstfdkmn commented Nov 22, 2022

Hello, we are now running 4.2.11. This has been tested again and generated the same result. We are going to be using the logical quota soon in our production zones and we evaluate this issue could be an obstacle. Could you let us know whether there is anything in our side that we can do as workaround until this issue is permanently fixed? Or expecting a solution to this as part of one of the next prc releases (if the issue is on the client side) would be much demanding? Thanks.

@d-w-moore
Copy link
Collaborator

@mstfdkmn Ok, will work to reproduce.

@d-w-moore
Copy link
Collaborator

d-w-moore commented Nov 29, 2022

@mstfdkmn So far unable to reproduce. My session is below:

$ imkdir qu
$ irule -r irods_rule_engine_plugin-logical_quotas-instance '{"operation": "logical_quotas_set_maximum_size_in_bytes", "collection": "/tempZone/home/rods/qu", "value": "175"}' null ruleExecOut
$ irule -r irods_rule_engine_plugin-logical_quotas-instance '{"operation": "logical_quotas_set_maximum_number_of_data_objects", "collection": "/tempZone/home/rods/qu", "value": "5"}' null ruleExecOut
$ irule -r irods_rule_engine_plugin-irods_rule_language-instance 'logical_quotas_start_monitoring_collection("/tempZone/home/rods/qu")' null ruleExecOutcOut
$ python  -c 'import irods.test.helpers as hs;s=hs.make_session();s.data_objects.put("data1","/tempZone/home/rods/qu/data1")'
$ ils -l qu
/tempZone/home/rods/qu:
  rods              0 demoResc           10 2022-11-29.12:04 & data1
$ irule -r irods_rule_engine_plugin-logical_quotas-instance '{"operation": "logical_quotas_get_collection_status", "collection" : "/tempZone/home/rods/qu"}' null ruleExecOut | jq .
{
  "irods::logical_quotas::maximum_number_of_data_objects": "5",
  "irods::logical_quotas::maximum_size_in_bytes": "175",
  "irods::logical_quotas::total_number_of_data_objects": "1",
  "irods::logical_quotas::total_size_in_bytes": "10"
}

I'd suggest starting from ground-zero , ie creating a collection, then adding quota limits and then starting to monitor the collection, to see if you can reproduce the error, then send me an exact replica of the commands you used.
Be sure also that you're not doing things that might "surprise" the plugin, like deleting a collection before you stop monitoring on it.... I've noticed invalid_param and re_runtime_error (-1205000, the same as the KeyError showed in your problem description) when I've done such things. These in themselves are hard to track down and reproduce but they happen in responses to the irule iCommand as well, and aren't necessarily indicative of a PRC problem.

@mstfdkmn
Copy link
Author

mstfdkmn commented Nov 29, 2022

Hi @d-w-moore, I am getting exactly the same issue again. First I will put here the steps that I took:

  • As a rodsuser I created a collection like you named:
✔ [Nov/29 20:18] vsc33586@login1 /data/leuven/335/vsc33586 $ iuserinfo
name: u0137480
id: 2844001
type: rodsuser
zone: icts_icts
✔ [Nov/29 20:15] vsc33586@login1 /data/leuven/335/vsc33586 $ imkdir qu
  • Later as a rodsadmin I applied the logical quota like in the order you made:
(base) u0137480@CRD-L-07856:~/projects/irods-acl-management$ iuserinfo
name: x0137480
id: 2848260
type: rodsadmin
zone: icts_icts

(base) u0137480@CRD-L-07856:~/projects/irods-acl-management$ irule -r irods_rule_engine_plugin-logical_quotas-instance '{"operation": "logical_quotas_set_maximum_size_in_bytes", "collection": "/icts_icts/home/u0137480/qu", "value": "175"}' null ruleExecOut
(base) u0137480@CRD-L-07856:~/projects/irods-acl-management$ irule -r irods_rule_engine_plugin-logical_quotas-instance '{"operation": "logical_quotas_set_maximum_number_of_data_objects", "collection": "/icts_icts/home/u0137480/qu", "value": "5"}' null ruleExecOut
(base) u0137480@CRD-L-07856:~/projects/irods-acl-management$ irule -r irods_rule_engine_plugin-irods_rule_language-instance 'logical_quotas_start_monitoring_collection("/icts_icts/home/u0137480/qu")' null ruleExecOutcOut
  • And I used this script and run it as a rodsuser:
✔ [Nov/29 20:19] vsc33586@login1 /data/leuven/335/vsc33586 $ cat test_lq.py
import os, os.path
from irods.session import iRODSSession

env_file = os.getenv('IRODS_ENVIRONMENT_FILE', os.path.expanduser('~/.irods/irods_environment.json'))
with iRODSSession(irods_env_file=env_file) as session:
    collection_path = '/icts_icts/home/u0137480/qu'
    file_path = '/data/leuven/335/vsc33586/alice1.txt'
    session.data_objects.put(file_path, collection_path) # + '/' + 'alice1.txt')
✔ [Nov/29 20:19] vsc33586@login1 /data/leuven/335/vsc33586 $ python test_lq.py
Traceback (most recent call last):
  File "/vsc-hard-mounts/leuven-data/335/vsc33586/test_lq.py", line 8, in <module>
    session.data_objects.put(file_path, collection_path) # + '/' + 'alice1.txt')
  File "/data/leuven/335/vsc33586/Anaconda/envs/prc-irods/lib/python3.9/site-packages/irods/manager/data_object_manager.py", line 162, in put
    o.write(chunk)
  File "/data/leuven/335/vsc33586/Anaconda/envs/prc-irods/lib/python3.9/site-packages/irods/data_object.py", line 177, in close
    self.conn.close_file(self.desc, **self.options)
  File "/data/leuven/335/vsc33586/Anaconda/envs/prc-irods/lib/python3.9/site-packages/irods/connection.py", line 616, in close_file
    self.recv()
  File "/data/leuven/335/vsc33586/Anaconda/envs/prc-irods/lib/python3.9/site-packages/irods/connection.py", line 132, in recv
    raise get_exception_by_code(msg.int_info, err_msg)
  File "/data/leuven/335/vsc33586/Anaconda/envs/prc-irods/lib/python3.9/site-packages/irods/exception.py", line 107, in get_exception_by_code
    exc_class = iRODSExceptionMeta.codes[ rounded_code( code ) ]
KeyError: -1205000

logs:
[2022-11-29T19:19:52.488Z][icts-t-cloud-leu-1] rsyslogd stdout | 2022-11-29T20:19:52.487695+01:00 icts rodsServer[38660]: icts_icts - remote addresses: 127.0.0.1, 2a02:2c40:0:221::3306:10 ERROR: iRODS Exception:#012 file: /repos/irods_rule_engine_plugin_logical_quotas/src/handler.cpp#012 function: auto irods::handler::pep_api_data_obj_close::post(const std::string &, const irods::instance_configuration_map &, std::list<boost::any> &, MsParamArray *, irods::callback &)::(anonymous class)::operator()(type-parameter-0-0 &, const type-parameter-0-1 &) const#012 line: 1295#012 code: -1205000 (RE_RUNTIME_ERROR)#012 message:#012 [-]#011/repos/irods_rule_engine_plugin_logical_quotas/src/handler.cpp:576:irods::error irods::handler::logical_quotas_count_total_number_of_data_objects(const std::string &, const irods::instance_configuration_map &, std::list<boost::any> &, MsParamArray *, irods::callback &) : status [RE_RUNTIME_ERROR] errno [] -- message [Logical Quotas Policy: Insufficient privileges]#012#012#012stack trace:#012--------------#012#012Dumping stack trace#012<0>#011Offset: 0x6e #011Address: 0x7fc153d8176e#011irods::exception::exception(long, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, unsigned int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)#012<1>#011Offset: 0xc7f #011Address: 0x7fc14c5560bf#011irods::handler::pep_api_data_obj_close::post(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::unordered_map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, irods::instance_configuration, std::__1::hash<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::equal_to<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, irods::instance_configuration> > > const&, std::__1::list<boost::any, std::__1::allocator<boost::any> >&, MsParamArray*, irods::callback&)#012<2>#011Offset: 0x22 #011Address: 0x7fc14c519512#011std::__1::__function::__func<irods::error (*)(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::unordered_map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, irods::instance_configuration, std::__1::hash<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::equal_to<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, irods::instance_configuration> > > const&, std::__1::list<boost::any, std::__1::allocator<boost::any> >&, MsParamArray*, irods::callback&), std::__1::allocator<irods::error (*)(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::unordered_map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, irods::instance_configuration, std::__1::hash<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::equal_to<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, irods::instance_configuration> > > const&, std::__1::list<boost::any, std::__1::allocator<boost::any> >&, MsParamArray*, irods::callback&)>, irods::error (std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::unordered_map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, irods::instance_configuration, std::__1::hash<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::equal_to<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, irods::instance_configuration> > > const&, std::__1::list<boost::any, std::__1::allocator<boost::any> >&, MsParamArray*, irods::callback&)>::operator()(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::unordered_map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, irods::instance_configuration, std::__1::hash<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::equal_to<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, irods::instance_configuration> > > const&, std::__1::list<boost::any, std::__1::allocator<boost::any> >&, MsParamArray*&&, irods::callback&)#012<3>#011Offset: #011Address: 0x7fc14c514625#011/usr/lib/irods/plugins/rule_engines/libirods_rule_engine_plugin-logical_quotas.so(+0x3d625) [0x7fc14c514625]#012<4>#011Offset: 0xe0 #011Address: 0x7fc152ecee10#011irods::error irods::pluggable_rule_engine<std::__1::tuple<> >::exec_rule<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, irods::plugin_context&, OpenedDataObjInp*>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::tuple<>&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&&, irods::plugin_context&&&, OpenedDataObjInp*&&, irods::callback)#012<5>#011Offset: 0x6f #011Address: 0x7fc152ececaf#011std::__1::__function::__func<irods::error irods::rule_engine_context_manager<std::__1::tuple<>, RuleExecInfo*, (irods::rule_execution_manager_pack)0>::exec_rule<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, irods::plugin_context&, OpenedDataObjInp*>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&&, irods::plugin_context&&&, OpenedDataObjInp*&&)::'lambda'(irods::re_pack_inp<std::__1::tuple<> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, irods::plugin_context&, OpenedDataObjInp*&&)::operator()(irods::re_pack_inp<std::__1::tuple<> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, irods::plugin_context&, OpenedDataObjInp*&&) const::'lambda'(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, irods::re_pack_inp<std::__1::tuple<> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, irods::plugin_context&, OpenedDataObjInp*&&), std::__1::allocator<irods::error irods::rule_engine_context_manager<std::__1::tuple<>, RuleExecInfo*, (irods::rule_execution_manager_pack)0>::exec_rule<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, irods::plugin_context&, OpenedDataObjInp*>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&&, irods::plugin_context&&&, OpenedDataObjInp*&&)::'lambda'(irods::re_pack_inp<std::__1::tuple<> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<

Ah, I see...Might it be the case that you run all as a rodsadmin? In my initial post I specified this like:

Other inputs:

This only happens for rodsusers. Rodsadmins can upload without an error.

Also, I a bit tried to investigate and it seems to me that this is more a plugin issue instead of PRC. Just guessing that the issue is because PRC triggers pep_api_data_obj_close_post which is different than what iput does. If you also think/evaluate this is a plugin issue, I guess this could be moved there.

@mstfdkmn
Copy link
Author

One more thing that: we have the metadata plugin configured just above the logical quota.

@alanking
Copy link
Contributor

The logical quotas REP handles that PEP: https://github.com/irods/irods_rule_engine_plugin_logical_quotas/blob/df75c52f6d8aa89a2b452aeb56626c2f944b5986/src/main.cpp#L59

I'm wondering if this has anything to do with PRC's "multi-1247" parallel transfer implementation, which uses replica_close? The REP also calculates usage for that API: https://github.com/irods/irods_rule_engine_plugin_logical_quotas/blob/df75c52f6d8aa89a2b452aeb56626c2f944b5986/src/handler.cpp#L1505-L1545 But... the error above (if it is indeed related) is coming from pep_api_data_obj_close_post... hm...

@d-w-moore
Copy link
Collaborator

@alanking I doubt this has to do with the multi-1247 parallel thing. Or at least I'm assuming the PRC-enabled put that @mstfdkmn used to produce this issue was a small file, ie single-buffer put, since the max bytes were set at 175.

@mstfdkmn
Copy link
Author

Another thing that could be useful:
The data object uploaded exists in the destination collection but it is not counted by the lq. Values of relevant attributes are still zero.

✔ [Nov/29 20:59] vsc33586@login1 /data/leuven/335/vsc33586 $ ils qu
/icts_icts/home/u0137480/qu:
  alice1.txt
✔ [Nov/29 20:59] vsc33586@login1 /data/leuven/335/vsc33586 $ imeta ls -C /icts_icts/home/u0137480/qu
AVUs defined for collection /icts_icts/home/u0137480/qu:
attribute: irods::logical_quotas::total_number_of_data_objects
value: 0
units:
----
attribute: irods::logical_quotas::total_size_in_bytes
value: 0
units:
----
attribute: irods::logical_quotas::maximum_size_in_bytes
value: 175
units:
----
attribute: irods::logical_quotas::maximum_number_of_data_objects
value: 5
units:

@d-w-moore
Copy link
Collaborator

@mstfdkmn Was it uploaded in its entirety ? How large is the uploaded file?

@mstfdkmn
Copy link
Author

mstfdkmn commented Nov 29, 2022

Yes, the status looks okay and the size is 74703 bytes.

/icts_icts/home/u0137480/qu:
  u0137480          0 default;netapp        74703 2022-11-29.20:19 & alice1.txt
        generic    /netapp/home/u0137480/qu/alice1.txt

@d-w-moore
Copy link
Collaborator

Ok, single buffer put, and you'd expect the file not to be successfully uploaded, since it exceeds the maximum bytes limitation. And I'm agreeing with what you said above, that this could be a plugin issue. If you hadn't sufficient permissions (as the stacktrace indicates) to upload the file, then why, I wonder, did the upload succeed.

To answer on another point, I did try the upload as a rodsuser and as rodsadmin, when trying to reproduce, but with a smaller file than the maximum_bytes limit. Maybe I misunderstood the problem description....

@alanking
Copy link
Contributor

Right, makes sense.

If we can write a rule which opens/creates a file and closes it such that pep_api_data_obj_close_post is triggered, we can confirm whether PRC is involved. As @mstfdkmn said, we can move this to the logical quotas repo if this is confirmed.

Perhaps something like this:

test_open_and_close {
    msiDataObjCreate("/tempZone/home/rods/foo", *fd);
    msiDataObjClose(*fd, *status);
}
INPUT null
OUTPUT ruleExecOut

@mstfdkmn
Copy link
Author

mstfdkmn commented Nov 29, 2022

Ok, single buffer put, and you'd expect the file not to be successfully uploaded, since it exceeds the maximum bytes limitation. And I'm agreeing with what you said above, that this could be a plugin issue. If you hadn't sufficient permissions (as the stacktrace indicates) to upload the file, then why, I wonder, did the upload succeed.

To answer on another point, I did try the upload as a rodsuser and as rodsadmin, when trying to reproduce, but with a smaller file than the maximum_bytes limit. Maybe I misunderstood the problem description....

As seen in my post before the last one, maximum_size_in_bytes and maximum_number_of_data_objects have not been exceeded. What I would expect is that the plugin should let uploads via prc, and counts those objects uploaded by prc and shows them as part of metadata values attached for monitoring attributes. Also we should not see any error both on the client returns and in the logs of iRODS.

@mstfdkmn
Copy link
Author

Right, makes sense.

If we can write a rule which opens/creates a file and closes it such that pep_api_data_obj_close_post is triggered, we can confirm whether PRC is involved. As @mstfdkmn said, we can move this to the logical quotas repo if this is confirmed.

Perhaps something like this:

test_open_and_close {
    msiDataObjCreate("/tempZone/home/rods/foo", *fd);
    msiDataObjClose(*fd, *status);
}
INPUT null
OUTPUT ruleExecOut

Hi @alanking, I have just tested via Metalnx which triggers the same pep. And the results in the iRODS' logs are similar.

[2022-11-29T20:44:32.391Z][icts-t-cloud-leu-1] rsyslogd stdout | 2022-11-29T21:44:32.390775+01:00 icts rodsServer[40112]: icts_icts - remote addresses: 127.0.0.1, 2a02:2c40:0:221::3306:10 ERROR: iRODS Exception:#012 file: /repos/irods_rule_engine_plugin_logical_quotas/src/handler.cpp#012 function: auto irods::handler::pep_api_data_obj_close::post(const std::string &, const irods::instance_configuration_map &, std::list<boost::any> &, MsParamArray *, irods::callback &)::(anonymous class)::operator()(type-parameter-0-0 &, const type-parameter-0-1 &) const#012 line: 1295#012 code: -1205000 (RE_RUNTIME_ERROR)#012 message:#012 [-]#011/repos/irods_rule_engine_plugin_logical_quotas/src/handler.cpp:576:irods::error irods::handler::logical_quotas_count_total_number_of_data_objects(const std::string &, const irods::instance_configuration_map &, std::list<boost::any> &, MsParamArray *, irods::callback &) : status [RE_RUNTIME_ERROR] errno [] -- message [Logical Quotas Policy: Insufficient privileges]#012#012#012stack trace:#012--------------#012#012Dumping stack trace#012<0>#011Offset: 0x6e #011Address: 0x7fc153d8176e#011irods::exception::exception(long, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, unsigned int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)#012<1>#011Offset: 0xc7f #011Address: 0x7fc14c5560bf#011irods::handler::pep_api_data_obj_close::post(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::unordered_map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, irods::instance_configuration, std::__1::hash<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::equal_to<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, irods::instance_configuration> > > const&, std::__1::list<boost::any, std::__1::allocator<boost::any> >&, MsParamArray*, irods::callback&)#012<2>#011Offset: 0x22 #011Address: 0x7fc14c519512#011std::__1::__function::__func<irods::error (*)(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::unordered_map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, irods::instance_configuration, std::__1::hash<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::equal_to<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, irods::instance_configuration> > > const&, std::__1::list<boost::any, std::__1::allocator<boost::any> >&, MsParamArray*, irods::callback&), std::__1::allocator<irods::error (*)(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::unordered_map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, irods::instance_configuration, std::__1::hash<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::equal_to<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, irods::instance_configuration> > > const&, std::__1::list<boost::any, std::__1::allocator<boost::any> >&, MsParamArray*, irods::callback&)>, irods::error (std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::unordered_map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, irods::instance_configuration, std::__1::hash<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::equal_to<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, irods::instance_configuration> > > const&, std::__1::list<boost::any, std::__1::allocator<boost::any> >&, MsParamArray*, irods::callback&)>::operator()(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::unordered_map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, irods::instance_configuration, std::__1::hash<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::equal_to<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, irods::instance_configuration> > > const&, std::__1::list<boost::any, std::__1::allocator<boost::any> >&, MsParamArray*&&, irods::callback&)#012<3>#011Offset: #011Address: 0x7fc14c514625#011/usr/lib/irods/plugins/rule_engines/libirods_rule_engine_plugin-logical_quotas.so(+0x3d625) [0x7fc14c514625]#012<4>#011Offset: 0xe0 #011Address: 0x7fc152ecee10#011irods::error irods::pluggable_rule_engine<std::__1::tuple<> >::exec_rule<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, irods::plugin_context&, OpenedDataObjInp*>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::tuple<>&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&&, irods::plugin_context&&&, OpenedDataObjInp*&&, irods::callback)#012<5>#011Offset: 0x6f #011Address: 0x7fc152ececaf#011std::__1::__function::__func<irods::error irods::rule_engine_context_manager<std::__1::tuple<>, RuleExecInfo*, (irods::rule_execution_manager_pack)0>::exec_rule<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, irods::plugin_context&, OpenedDataObjInp*>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&&, irods::plugin_context&&&, OpenedDataObjInp*&&)::'lambda'(irods::re_pack_inp<std::__1::tuple<> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, irods::plugin_context&, OpenedDataObjInp*&&)::operator()(irods::re_pack_inp<std::__1::tuple<> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, irods::plugin_context&, OpenedDataObjInp*&&) const::'lambda'(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, irods::re_pack_inp<std::__1::tuple<> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, irods::plugin_context&, OpenedDataObjInp*&&), std::__1::allocator<irods::error irods::rule_engine_context_manager<std::__1::tuple<>, RuleExecInfo*, (irods::rule_execution_manager_pack)0>::exec_rule<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, irods::plugin_context&, OpenedDataObjInp*>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&&, irods::plugin_context&&&, OpenedDataObjInp*&&)::'lambda'(irods::re_pack_inp<std::__1::tuple<> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<

And these are the possible relavant errors in the logs of Metalnx:

[2022-11-29T20:48:51.699Z][icts-t-cloud-hev-3] 2022-11-29 20:48:51 ERROR IRODSFileOutputStream:259 - JargonException caught in constructor, rethrow as IOException
[2022-11-29T20:48:51.699Z][icts-t-cloud-hev-3] 2022-11-29 20:48:51 ERROR IRODSMidLevelProtocol:1636 - IRODS error occured msg : -1205000

@d-w-moore
Copy link
Collaborator

@mstfdkmn I'm a little confused as to the problem being described then... if alice1.txt is 75000 bytes and the maximum # bytes are set at 175, you're going over quota for total bytes uploaded, correct?

@mstfdkmn
Copy link
Author

@d-w-moore sorry I need to correct myself for my last post. Indeed there are two points - one is what you said: it should not exceeds the quota set, and the second one is what I tried to state: regardless of the quota set (you could still have room to upload), the plugin should let the uploads done by prc without creating any errors. And those uploads should be counted by the lq plugin like uploads done by iput. This is a new test for the second point (mine):

(base) u0137480@CRD-L-07856:~/projects/irods-acl-management$ irule -r irods_rule_engine_plugin-logical_quotas-instance '{"operation": "logical_quotas_get_collection_status", "collection" : "/icts_icts/home/u0137480/qu"}' null ruleExecOut | jq .
{
  "irods::logical_quotas::maximum_number_of_data_objects": "5",
  "irods::logical_quotas::maximum_size_in_bytes": "17500000",
  "irods::logical_quotas::total_number_of_data_objects": "0",
  "irods::logical_quotas::total_size_in_bytes": "0"
}
✔ [Nov/29 22:03] vsc33586@login1 /data/leuven/335/vsc33586 $ python test_lq.py
Traceback (most recent call last):
  File "/vsc-hard-mounts/leuven-data/335/vsc33586/test_lq.py", line 8, in <module>
    session.data_objects.put(file_path, collection_path) # + '/' + 'alice1.txt')
  File "/data/leuven/335/vsc33586/Anaconda/envs/prc-irods/lib/python3.9/site-packages/irods/manager/data_object_manager.py", line 162, in put
    o.write(chunk)
  File "/data/leuven/335/vsc33586/Anaconda/envs/prc-irods/lib/python3.9/site-packages/irods/data_object.py", line 177, in close
    self.conn.close_file(self.desc, **self.options)
  File "/data/leuven/335/vsc33586/Anaconda/envs/prc-irods/lib/python3.9/site-packages/irods/connection.py", line 616, in close_file
    self.recv()
  File "/data/leuven/335/vsc33586/Anaconda/envs/prc-irods/lib/python3.9/site-packages/irods/connection.py", line 132, in recv
    raise get_exception_by_code(msg.int_info, err_msg)
  File "/data/leuven/335/vsc33586/Anaconda/envs/prc-irods/lib/python3.9/site-packages/irods/exception.py", line 107, in get_exception_by_code
    exc_class = iRODSExceptionMeta.codes[ rounded_code( code ) ]
KeyError: -1205000
✘ [Nov/29 22:03] vsc33586@login1 /data/leuven/335/vsc33586 $ imeta ls -C /icts_icts/home/u0137480/qu
AVUs defined for collection /icts_icts/home/u0137480/qu:
attribute: irods::logical_quotas::maximum_number_of_data_objects
value: 5
units:
----
attribute: irods::logical_quotas::total_number_of_data_objects
value: 0
units:
----
attribute: irods::logical_quotas::total_size_in_bytes
value: 0
units:
----
attribute: irods::logical_quotas::maximum_size_in_bytes
value: 17500000
units:
✔ [Nov/29 22:03] vsc33586@login1 /data/leuven/335/vsc33586 $ ils /icts_icts/home/u0137480/qu
/icts_icts/home/u0137480/qu:
  alice1.txt

@mstfdkmn
Copy link
Author

I think this problem is the same as this one irods/irods_rule_engine_plugin_logical_quotas#75 . The roots seems the same. But I guess duplicating it - without awareness the core problem.

@d-w-moore
Copy link
Collaborator

Yes it does look similar to that issue.

One more thing that: we have the metadata plugin configured just above the logical quota.

Is that the metadata guard plugin ?

@d-w-moore
Copy link
Collaborator

@alanking

If we can write a rule which opens/creates a file and closes it such that pep_api_data_obj_close_post is triggered, we can confirm whether PRC is involved.
Tried your idea:

main()
{
  msiDataObjCreate("/tempZone/home/rods/qu/data.dat","",*fd);
  writeLine("stdout","fd=[*fd]");
  msiDataObjClose(*fd,*junk);
  writeLine("stdout","junk=[*junk]");
}

INPUT null
OUTPUT ruleExecOut

Result: it does seem pep_api_data_obj_close_post works fine from irule. The file is created; and no messages appeared in the logs nor errors spooled from the irule client... so I guess does kind of implicate the PRC.

@alanking
Copy link
Contributor

It did occur to me that I neglected to include writing data to the object so maybe it wouldn't make an impact on logical quotas in this instance. Could you write a few bytes and see if that has an impact?

@d-w-moore
Copy link
Collaborator

d-w-moore commented Nov 30, 2022

I actually did that , too, last night, and it didn't make a difference... sorry :/

main()
{ 
  msiDataObjCreate("/tempZone/home/rods/qu/thing.dat","",*fd);
  writeLine("stdout","fd=[*fd]");
  *y = msiDataObjWrite( *fd, "hello", 5);
  writeLine("stdout","y=[*y]");
  msiDataObjClose(*fd,*junk);
  writeLine("stdout","junk=[*junk]");
}

INPUT null
OUTPUT ruleExecOut

@mstfdkmn
Copy link
Author

Yes it does look similar to that issue.

One more thing that: we have the metadata plugin configured just above the logical quota.

Is that the metadata guard plugin ?

If you meant the metadata guard plugin was enabled, then yes - we use those two plugins together.

@d-w-moore
Copy link
Collaborator

@mstfdkmn - The metadata guard plugin seems to be the key. With that loaded and configured, I was finally able to reproduce this issue.

@mstfdkmn
Copy link
Author

Great! Thanks.

@d-w-moore
Copy link
Collaborator

d-w-moore commented Dec 1, 2022

@mstfdkmn We should be able to release 4.2.11.1 of this plugin, which will incorporate a couple of changes that allow it to work for a rodsuser, and with the metadata plugin configured.

@mstfdkmn
Copy link
Author

mstfdkmn commented Dec 7, 2022

We would be pleased if there is a progress on this issue because it seems that any set quota can be penetrated by uploading data via PRC.
Also, I one more time tested this issue exists as well without configuring the metadata plugin. Thanks.

@d-w-moore
Copy link
Collaborator

@mstfdkmn You are able to exceed set quotas with the PRC, even with the metadata guard plugin not installed and configured? OK, I'll check into it.

@mstfdkmn
Copy link
Author

mstfdkmn commented Dec 7, 2022

Yes, installed but not configured. Meaning removed from /etc/irods/server_config.json

@trel
Copy link
Member

trel commented Dec 8, 2022

Yes, installed but not configured.

Then this means we DO NOT yet understand what is happening.

The metadata guard being installed we thought was triggering this issue (irods/irods_rule_engine_plugin_logical_quotas#63) (preventing non-admins from proceeding), which is already fixed in the logical quotas repository, and would be in a 4.2.11.1 (or 4.2.12.0) release.

@d-w-moore
Copy link
Collaborator

d-w-moore commented Dec 8, 2022

We would be pleased if there is a progress on this issue because it seems that any set quota can be penetrated by uploading data via PRC.
Also, I one more time tested this issue exists as well without configuring the metadata plugin. Thanks.

@mstfdkmn :

Two possible interpretations here (and I'm confused as to which you mean, so maybe you can help me out) :

(1) If "this issue [still] exists_ [without metadata plugin configured]" means the raising of irods error -1205000 -- which I was able to reproduce only with the metadata guard installed+configured but not otherwise -- then I am surprised at this, and will probably need either a from-ground-zero procedure for reproducing, or perhaps we do a video chat.

(2) If by that you mean simply that one is able, via the PRC (or any client using streaming, ie open - write - close instead of an actual PUT), to exceed quota exactly once but with CREATE's and WRITE's limited afterward (see this commit message in logical quotas), then ( responding to your concern, @trel ) ... maybe we do understand what is going on after all. If that's the case, the one-time breaking of quotas is a feature / bug of the plugin and not a PRC concern.

Continuing to check and verify on (2), which I believe is the more likely interpretation of your exact meaning in the previous post ....

@d-w-moore
Copy link
Collaborator

d-w-moore commented Dec 8, 2022

@mstfdkmn @trel ... verified.
With a quota of 10,000 bytes in effect for the /tempZone/home/rods/qu collection, a rodsadmin gets this error too, as we'd expect:

$ python3 -ic 'import irods; import irods.test.helpers as he; ses = he.make_session(); ses.data_objects.open("/tempZone/home/rods/qu/one.dat","a").write(b"_"*1100
0)'                                                                             
>>>                                         
$ ils -l              
/tempZone/home/rods:                          
  C- /tempZone/home/rods/qu             
$ ils -l qu           
/tempZone/home/rods/qu:                
  rods              0 demoResc        11000 2022-12-08.07:21 & one.dat
$ python3 -ic 'import irods; import irods.test.helpers as he; ses = he.make_session(); ses.data_objects.open("/tempZone/home/rods/qu/two.dat","a").write(b"_"*2000
)'                                       
Traceback (most recent call last):                                                
  File "<string>", line 1, in <module>                                   
  File "/home/daniel/python-irodsclient/irods/manager/data_object_manager.py", line 332, in open
    desc = conn.recv().int_info
  File "/home/daniel/python-irodsclient/irods/connection.py", line 133, in recv
    raise get_exception_by_code(msg.int_info, err_msg)
irods.exception.SYS_INVALID_INPUT_PARAM: Logical Quotas Policy Violation: Adding object exceeds maximum data size in bytes limit
>>>    

However, I still have yet to reproduce the -1205000 error (the actual problem described in the title of this issue) without the metadata guard plugin configured and active. So, @mstfdkmn , if you can do so, perhaps we should get on a video chat so that you can show me how.

@mstfdkmn
Copy link
Author

mstfdkmn commented Dec 8, 2022

Hello, I again tested in three different new environments (also with the postgres db configuration - normally we run mysql) and I can verify that I am seeing the same issues ( -1205000 error and exceeding set quotas with the PRC) without the metadata guard plugin (not installed and so not configured). Therefore your suggestion sounds great. At any convenient time of you, we can have a video call to show you what I am doing/seeing. Thanks a lot.

@d-w-moore
Copy link
Collaborator

d-w-moore commented Dec 9, 2022

@mstfdkmn - I was able to reproduce irods error -1205000 (RE_RUNTIME_ERROR) from a rodsuser put with PRC this morning, without a loaded and configured metadata guard. So, no driving need for us to meet now. Unfortunately, the status of an fix for 4.2.11 is still not definite. I will discuss with the team soon, however.

@mstfdkmn
Copy link
Author

mstfdkmn commented Dec 9, 2022

Alright thanks. Btw, I missed your meeting request since I didn't expect we could meet that early and this afternoon I took some hours off. Sorry about:(

@d-w-moore
Copy link
Collaborator

No worries about that @mstfdkmn . I would like to impart, however, that after discussion with the iRODS Team and a little further experimentation, it seems that either an istream write or a PRC "put" call (and keep in mind both of these are OPEN / WRITE / CLOSE operation sequences instead of actual PUT) will invoke the RE_RUNTIME_ERROR with the error message [Logical Quotas Policy: Insufficient privileges]. This happens even writing just a few bytes, ie. far below quota.

The error occurs in the switch_user used in the logical quotas plugin. Unfortunately a secure fix for this has yet to be implemented and may not be possible prior to a 4.2.12 iRODS release, as it would have to rely on use of the ADMIN_KW in the metadata API (unsupported in 4.2.11).

@mstfdkmn
Copy link
Author

mstfdkmn commented Dec 9, 2022

Okay Daniel thanks. This also implies that a solution regarding with this to 4.3.x should not be expected before seeing that fix in 4.2.12?

@d-w-moore
Copy link
Collaborator

@mstfdkmn I believe that to be the case, yes. The solution has yet to be implemented.

@trel
Copy link
Member

trel commented Dec 9, 2022

Adding the admin keyword to the metadata API is irods/irods#6161 and irods/irods#6124 and will be in 4.2.12 and was already included in 4.3.0.

@d-w-moore
Copy link
Collaborator

d-w-moore commented Dec 10, 2022

Adding the admin keyword to the metadata API is irods/irods#6161 and irods/irods#6124 and will be in 4.2.12 and was already included in 4.3.0.

Ah, right. So theoretically a 4.3.0.1 release of the logical quotas plugin could offer a solution.

@trel
Copy link
Member

trel commented Dec 10, 2022

Yes, we could provide a "secure fix" with the admin keyword approach in a 4.3.0.1 release.

@d-w-moore
Copy link
Collaborator

d-w-moore commented Dec 12, 2022

Created an issue in the Logical Quotas plugin repo , including how to reproduce this same error -1205000, with the only plugin installed or active being logical quotas:
irods/irods_rule_engine_plugin_logical_quotas#84
In that issue, istream is used rather than PRC to evoke the error, but the same effect can be achieved in PRC with this put script and a single argument specifying a very small file to upload:

#!/usr/bin/env python3

import os, sys
from os.path import basename
from irods.test.helpers import (make_session, home_collection)

s=make_session()

filename = sys.argv[1]
s.data_objects.put(
  filename,
  "{home}/quotaDir/{basenm}".format(home = home_collection(s),
                                    basenm = basename(filename))
)

@d-w-moore
Copy link
Collaborator

Due to the above, this is not a PRC issue and therefore can be closed here....

@alanking alanking added the bug label Dec 12, 2022
d-w-moore added a commit to d-w-moore/python-irodsclient that referenced this issue Jan 12, 2023
Previously, -1205000 wasn't defined in irods/exception.py, and as
a result, the name and details of such an exception were not being
reported from a server call.
alanking pushed a commit that referenced this issue Jan 12, 2023
Previously, -1205000 wasn't defined in irods/exception.py, and as
a result, the name and details of such an exception were not being
reported from a server call.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

No branches or pull requests

4 participants