search

irods / irods_rule_engine_plugin_python

BSD 3-Clause "New" or "Revised" License
10 stars 14 forks source link

UTF-8 error triggering when pep_database_check_auth_xx or pep_api_auth_response_xx is called #204

Open LyneVdV opened 1 month ago

LyneVdV commented 1 month ago

iRODS 4.3.1

The following error occurs when a rule like def pep_database_check_auth_post(rule_args, callback, rei): pass is triggered

{"log_category":"rule_engine","log_level":"error","log_message":"caught python exception","python_exception":"UnicodeDecodeError: 'utf-8' codec can't decode byte 0xfa in position 0: invalid start byte\n","request_api_name":"","request_api_number":110000,"request_api_version":"d","request_client_user":"rods","request_host":"127.0.0.1","request_proxy_user":"rods","request_release_version":"rods4.3.1","rule_engine_plugin":"python","server_host":"lyne-virtual-machine","server_pid":2765398,"server_timestamp":"2024-05-31T09:21:07.277Z","server_type":"agent","server_zone":"tempZone"}
{"log_category":"api","log_level":"info","log_message":"rsAuthCheck: chlCheckAuth status = -1","request_api_name":"","request_api_number":110000,"request_api_version":"d","request_client_user":"rods","request_host":"127.0.0.1","request_proxy_user":"rods","request_release_version":"rods4.3.1","server_host":"lyne-virtual-machine","server_pid":2765398,"server_timestamp":"2024-05-31T09:21:07.277Z","server_type":"agent","server_zone":"tempZone"}
{"log_category":"api","log_level":"info","log_message":"Error occurred invoking auth plugin operation [Unknown iRODS error: rcAuthCheck failed.\n\n] [ec=-1]","request_api_name":"","request_api_number":110000,"request_api_version":"d","request_client_user":"rods","request_host":"127.0.0.1","request_proxy_user":"rods","request_release_version":"rods4.3.1","server_host":"lyne-virtual-machine","server_pid":2765398,"server_timestamp":"2024-05-31T09:21:07.277Z","server_type":"agent","server_zone":"tempZone"}
{"log_category":"authentication","log_level":"info","log_message":"Error occurred while authenticating user [rods] [Unknown iRODS error: failed to perform request\n\n] [ec=-1]","server_host":"lyne-virtual-machine","server_pid":16233,"server_timestamp":"2024-05-31T09:21:07.483Z","server_type":"server","server_zone":"tempZone"}
{"log_category":"server","log_level":"error","log_message":"Caught exception in migrate_delay_server(): iRODS Exception:\n    file: /irods_source/lib/core/src/client_connection.cpp\n    function: void irods::experimental::client_connection::connect_and_login(const std::string &, const int, const irods::experimental::fully_qualified_username &)\n    line: 161\n    code: -178000 (AUTHENTICATION_ERROR)\n    message:\n        Client login error\nstack trace:\n--------------\n 0# irods::stacktrace::dump() const in /lib/libirods_common.so.4.3.1\n 1# irods::exception::assemble_full_display_what() const in /lib/libirods_common.so.4.3.1\n 2# irods::exception::what() const in /lib/libirods_common.so.4.3.1\n 3# std::__1::__function::__func<initServerMain(RsComm*, bool, bool)::$_13, std::__1::allocator<initServerMain(RsComm*, bool, bool)::$_13>, void ()>::operator()() at rodsServer.cpp:?\n 4# irods::experimental::cron::cron_task::operator()() in /usr/sbin/irodsServer\n 5# irods::experimental::cron::cron::run() in /usr/sbin/irodsServer\n 6# void* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, main::$_10> >(void*) at rodsServer.cpp:?\n 7# 0x00007EC733A94AC3 in /lib/x86_64-linux-gnu/libc.so.6\n 8# 0x00007EC733B26850 in /lib/x86_64-linux-gnu/libc.so.6\n\n","server_host":"lyne-virtual-machine","server_pid":16233,"server_timestamp":"2024-05-31T09:21:07.578Z","server_type":"server","server_zone":"tempZone"}

Same for the any pep_database_check_auth_xx or pep_api_auth_response_xx (maybe others as well but they are not triggered so no error pops up).

If the same rule is written in irods rule langage / plugin, there is no issue. Any clue :) ?

MartinFlores751 commented 3 weeks ago

After some investigation, the issue is likely to deal with how we serialize the _response variable.

In a group debugging session using GDB, we were able to step through the input variables and see that all but one of the variables turned out to be useable.

An example of what variables are processed: https://docs.irods.org/4.3.2/plugins/dynamic_policy_enforcement_points/#dynamic-pep-signatures

The specific argument variables for the pep can be found here: https://docs.irods.org/4.3.2/plugins/dynamic_policy_enforcement_points/#database

Viewing the variable in GDB showed that it was not a UTF encoded item, and that it was likely some other form of data.

Following that, we decided to test this with a Rule Language pep to make certain that the issue is within the PREP. We used the following to test this:

pep_database_check_auth_post(*INSTANCE_NAME, *CONTEXT, *OUT, *SCHEME, *CHALLENGE, *RESPONSE, *USERNAME, *USERPRIV, *CLIENTPRIV) {
  writeLine("serverLog", *RESPONSE);
}

Viewing the logs shows the following results:

...
{
  "log_category": "api",
  "log_level": "info",
  "log_message": "Error occurred invoking auth plugin operation [[json.exception.type_error.316] invalid UTF-8 byte at index 23: 0xB2]",
  "request_api_name": "",
  "request_api_number": 110000,
  "request_api_version": "d",
  "request_client_user": "rods",
  "request_host": "172.23.0.3",
  "request_proxy_user": "rods",
  "request_release_version": "rods4.3.2",
  "server_host": "a94605ed46ab",
  "server_pid": 1794,
  "server_timestamp": "2024-06-11T22:27:00.997Z",
  "server_type": "agent",
  "server_zone": "tempZone"
}                                                                                                                                                                                                                                                                                                                                                                                             
{
  "log_category": "authentication",
  "log_level": "info",
  "log_message": "Error occurred while authenticating user [rods] [SYS_INTERNAL_ERR: failed to perform request\n\n] [ec=-154000]",
  "server_host": "a94605ed46ab",
  "server_pid": 1597,
  "server_timestamp": "2024-06-11T22:27:00.998Z",
  "server_type": "server",
  "server_zone": "tempZone"
}  
...

In this case, we can see that both the PREP and iRODS Rule Language have issue with "decoding" the _response variable.

In terms of solutions, fixing this "properly", i.e., fixing the encoding of the variable, would likely affect many parts of the system.

A temporary solution, at least for the PREP, may be to "blank" the variable out.

LyneVdV commented 4 days ago

Thank you for narrowing down the issue ! I will make sure not to use the RESPONSE variable in the irods rule language. I am not sure what "blanking" the variable out means but not using/calling that pep at all with the PREP works (i.e. replacing it by using the irods rule language for that specific pep without the RESPONSE variable).

alanking commented 4 days ago

I believe the "blanking" is a proposed solution which would need to be implemented in the plugin itself (see https://github.com/irods/irods_rule_engine_plugin_python/pull/207). So, the "temporary solution" is not so much a workaround for one's rulebase as it is a relatively isolated fix in the C++ in lieu of the "proper" fix.