Upgrade for iRODS 4.3 #3

mikkonie · 2023-02-01T08:05:45Z

mikkonie · 2024-10-15T11:41:40Z

The lastest (pre-?) release of Davrods for iRODS 4.3 is 4.3.0_1.5.0. I'll have to see how well it works with iRODS 4.3.3

Since that release there doesn't seem to have been any work for iRODS 4.3 support. However, I noticed this comment for two weeks ago stating that they would be continuing this work "soon".

I should maybe have checked on the status of Davrods dev sooner when I restarted my work on iRODS 4.3 upgrades..

Update: Then again rit-davrods has been updated for iRODS 4.3.2. Perhaps this will work.

mikkonie · 2024-11-08T15:05:53Z

Got this to a point where the server is up and the module is loaded. No errors anywhere and auth request is successfully passed from Davrods to SODAR through iRODS. However, after a successful auth with SODAR via the custom PAM module, Davrods asks for authentication again and we are most definitely not authenticated.

At the moment I can't completely discount this being due to some config error in my environment. I'll have to pin down the root cause.

What exactly happens:

Apache runs without errors
Davrods module is installed
Link from SODAR correctly directs to Davrods
Davrods asks for auth
Auth request reaches iRODS from Davrods
Auth request reaches SODAR from iRODS (using SODAR auth API for iRODS)
SODAR responds with 200 OK
???
Davrods returns 401 and prompts for login again

Davrods log:

davrods-1     | localhost:80 172.20.0.3 - alice [08/Nov/2024:14:46:20 +0000] "GET /sodarZone/projects/a0/a076281e-d0f7-44fc-bca8-fe4580ff3503/sample_data/study_ae75232c-c5dc-4f5c-b209-97fc0b1edb45/assay_a5fffa61-8638-483a-86a7-e072f9886e7d/P1001-N1-DNA1-WGS1/bam/P1001-N1_28zv6aa9l6dqe0za.bam HTTP/1.1" 401 668 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36"

iRODS log with debug level enabled for all logging categories:

 {"log_category":"server","log_level":"debug","log_message":"Agent process [1750] started for puser=[alice] and cuser=[alice] from [172.20.0.7]","server_host":"irods","server_pid":1728,"server_timestamp":"2024-11-08T14:47:40.885Z","server_type":"server","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"debug","log_message":"hash_rules_with_copy: rulebases = [core]; digest = [3ac8edec33652c0fc507dd37b066bbef]","server_host":"irods","server_pid":1750,"server_timestamp":"2024-11-08T14:47:40.913Z","server_type":"agent","server_zone":"sodarZone"}
 {"dynamic_pep_rule_regex":"[^ ]*pep_[^ ]*_(pre|post)","instance_name":"irods_rule_engine_plugin-python-instance","log_category":"rule_engine","log_level":"debug","log_message":"No regexes found in server_config for Python RE - using default regexes","rule_engine_plugin":"python","server_host":"irods","server_pid":1750,"server_timestamp":"2024-11-08T14:47:40.927Z","server_type":"agent","server_zone":"sodarZone","static_pep_rule_regex":"ac[^ ]*"}
 {"log_category":"agent","log_level":"debug","log_message":"Unpacking byte buffer based on packing instruction [sslStartInp_PI]","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":1750,"server_timestamp":"2024-11-08T14:47:40.980Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"debug","log_message":"Unpacking byte buffer based on packing instruction [pamAuthRequestInp_PI]","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":1750,"server_timestamp":"2024-11-08T14:47:40.985Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"debug","log_message":"Unpacking byte buffer based on packing instruction [sslEndInp_PI]","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":1750,"server_timestamp":"2024-11-08T14:47:41.296Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"debug","log_message":"[close_all_l1_descriptors:949] Closing all L1 descriptors ...","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":1750,"server_timestamp":"2024-11-08T14:47:41.296Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"debug","log_message":"Agent [1750] exiting with status = 0","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":1750,"server_timestamp":"2024-11-08T14:47:41.297Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent_factory","log_level":"debug","log_message":"Agent process [1750] exited with status [0].","server_host":"irods","server_pid":1729,"server_timestamp":"2024-11-08T14:47:41.322Z","server_type":"agent_factory","server_zone":"sodarZone"}

For a trace level log, see comment below.

Things to note:

Native auth works
PAM auth fails both with my custom PAM plugin and LDAP auth via SSSD
- Hence, the custom plugin shouldn't be at fault
- Also, both work with iinit and the same credentials..

mikkonie · 2024-11-11T15:30:45Z

Log of a failed login with all log categories set to trace:

 {"log_category":"server","log_level":"debug","log_message":"Agent process [548] started for puser=[alice] and cuser=[alice] from [172.20.0.7]","server_host":"irods","server_pid":526,"server_timestamp":"2024-11-11T15:06:16.638Z","server_type":"server","server_zone":"sodarZone"}
 {"log_category":"server","log_level":"trace","log_message":"Cannot get log level for log category [genquery2]. Defaulting to [info].","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.638Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"debug","log_message":"hash_rules_with_copy: rulebases = [core]; digest = [3ac8edec33652c0fc507dd37b066bbef]","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.659Z","server_type":"agent","server_zone":"sodarZone"}
 {"dynamic_pep_rule_regex":"[^ ]*pep_[^ ]*_(pre|post)","instance_name":"irods_rule_engine_plugin-python-instance","log_category":"rule_engine","log_level":"debug","log_message":"No regexes found in server_config for Python RE - using default regexes","rule_engine_plugin":"python","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.672Z","server_type":"agent","server_zone":"sodarZone","static_pep_rule_regex":"ac[^ ]*"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [20005] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.674Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [20006] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.676Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [110000] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.677Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [20008] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.680Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [20007] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.681Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [120000] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.681Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [1300] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.682Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [20000] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.683Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [20004] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.684Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [20001] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.685Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [20002] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.685Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [20012] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.686Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"Added API number [20003] to the client API allowlist.","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.688Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [20005] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.688Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [20006] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.689Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [110000] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.690Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [20008] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.691Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [20007] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.691Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [120000] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.691Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [1300] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.692Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [20000] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.692Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [20004] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.692Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [20001] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.692Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [20002] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.693Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [20012] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.693Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"api","log_level":"trace","log_message":"API number [20003] has already been added to the client API allowlist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.694Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_open_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.706Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_open_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.721Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_gen_query_access_control_setup_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.722Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_gen_query_access_control_setup_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.722Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_gen_query_access_control_setup_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.722Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_gen_query_access_control_setup_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.722Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_gen_query_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.722Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_get_rcs_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.722Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_get_rcs_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.722Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_gen_query_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.724Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_gen_query_access_control_setup_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.724Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_gen_query_access_control_setup_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.724Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_gen_query_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.724Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_get_rcs_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.724Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_get_rcs_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.724Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_gen_query_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.728Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_body_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.731Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_header_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.731Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_header_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.731Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_body_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.731Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_header_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.731Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_header_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_body_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_body_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_body_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_header_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_header_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_body_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_agent_start_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_agent_start_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_header_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_header_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_body_pre] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_body_post] passes regex test, but does not exist","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"trace","log_message":"Verifying if API number is supported ...","request_api_name":"GET_MISC_SVR_INFO_AN","request_api_number":700,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"trace","log_message":"Checking API permissions ...","request_api_name":"GET_MISC_SVR_INFO_AN","request_api_number":700,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.732Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_api_get_misc_svr_info_pre] passes regex test, but does not exist","request_api_name":"GET_MISC_SVR_INFO_AN","request_api_number":700,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_api_get_misc_svr_info_post] passes regex test, but does not exist","request_api_name":"GET_MISC_SVR_INFO_AN","request_api_number":700,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_body_pre] passes regex test, but does not exist","request_api_name":"GET_MISC_SVR_INFO_AN","request_api_number":700,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_header_pre] passes regex test, but does not exist","request_api_name":"GET_MISC_SVR_INFO_AN","request_api_number":700,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_header_post] passes regex test, but does not exist","request_api_name":"GET_MISC_SVR_INFO_AN","request_api_number":700,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_body_post] passes regex test, but does not exist","request_api_name":"GET_MISC_SVR_INFO_AN","request_api_number":700,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_header_pre] passes regex test, but does not exist","request_api_name":"GET_MISC_SVR_INFO_AN","request_api_number":700,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_header_post] passes regex test, but does not exist","request_api_name":"GET_MISC_SVR_INFO_AN","request_api_number":700,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_body_pre] passes regex test, but does not exist","request_api_name":"GET_MISC_SVR_INFO_AN","request_api_number":700,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_body_post] passes regex test, but does not exist","request_api_name":"GET_MISC_SVR_INFO_AN","request_api_number":700,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"trace","log_message":"Verifying if API number is supported ...","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"trace","log_message":"Checking API permissions ...","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"debug","log_message":"Unpacking byte buffer based on packing instruction [sslStartInp_PI]","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_api_ssl_start_pre] passes regex test, but does not exist","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_api_ssl_start_post] passes regex test, but does not exist","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_body_pre] passes regex test, but does not exist","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_header_pre] passes regex test, but does not exist","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_header_post] passes regex test, but does not exist","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_body_post] passes regex test, but does not exist","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.733Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_header_pre] passes regex test, but does not exist","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.740Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_header_post] passes regex test, but does not exist","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.740Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_body_pre] passes regex test, but does not exist","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.740Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_body_post] passes regex test, but does not exist","request_api_name":"SSL_START_AN","request_api_number":1100,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.740Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"trace","log_message":"Verifying if API number is supported ...","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.740Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"trace","log_message":"Checking API permissions ...","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.740Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"debug","log_message":"Unpacking byte buffer based on packing instruction [pamAuthRequestInp_PI]","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.740Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_api_pam_auth_request_pre] passes regex test, but does not exist","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:16.740Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_update_pam_password_pre] passes regex test, but does not exist","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.055Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"database","log_level":"trace","log_message":"attempting connection to database using dsn [iRODS Catalog]","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.055Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_body_pre] passes regex test, but does not exist","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.069Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_header_pre] passes regex test, but does not exist","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.069Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_header_post] passes regex test, but does not exist","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.069Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_body_post] passes regex test, but does not exist","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.069Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_header_pre] passes regex test, but does not exist","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.069Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_header_post] passes regex test, but does not exist","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_body_pre] passes regex test, but does not exist","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_body_post] passes regex test, but does not exist","request_api_name":"PAM_AUTH_REQUEST_AN","request_api_number":725,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"trace","log_message":"Verifying if API number is supported ...","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"trace","log_message":"Checking API permissions ...","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"debug","log_message":"Unpacking byte buffer based on packing instruction [sslEndInp_PI]","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_api_ssl_end_pre] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_api_ssl_end_post] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_body_pre] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_header_pre] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_header_post] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_write_body_post] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_header_pre] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_header_post] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_body_pre] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_read_body_post] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.070Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_agent_stop_pre] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.071Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_network_agent_stop_post] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.071Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"debug","log_message":"[close_all_l1_descriptors:949] Closing all L1 descriptors ...","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.071Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_close_pre] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.071Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"rule_engine","log_level":"trace","log_message":"Rule [pep_database_close_post] passes regex test, but does not exist","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.071Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent","log_level":"debug","log_message":"Agent [548] exiting with status = 0","request_api_name":"SSL_END_AN","request_api_number":1101,"request_api_version":"d","request_client_user":"alice","request_host":"172.20.0.7","request_proxy_user":"alice","request_release_version":"rods4.3.3","server_host":"irods","server_pid":548,"server_timestamp":"2024-11-11T15:06:17.071Z","server_type":"agent","server_zone":"sodarZone"}
 {"log_category":"agent_factory","log_level":"trace","log_message":"Reaped agent [548] ...","server_host":"irods","server_pid":527,"server_timestamp":"2024-11-11T15:06:17.076Z","server_type":"agent_factory","server_zone":"sodarZone"}
 {"log_category":"agent_factory","log_level":"debug","log_message":"Agent process [548] exited with status [0].","server_host":"irods","server_pid":527,"server_timestamp":"2024-11-11T15:06:17.076Z","server_type":"agent_factory","server_zone":"sodarZone"}
 {"log_category":"agent_factory","log_level":"trace","log_message":"Removing agent PID [548] from replica access table ...","server_host":"irods","server_pid":527,"server_timestamp":"2024-11-11T15:06:17.076Z","server_type":"agent_factory","server_zone":"sodarZone"}

mikkonie · 2024-11-13T08:25:25Z

iRODS support suggested this problem may be due to a PAM auth incompatibility between Davrods and iRODS 4.3 and it could not work to begin with.

iRODS devs have opened an issue for dealing with this, see irods/irods#8016.

However, Davrods should still be able to do the "legacy" style PAM auth. But how to make that work with 4.3.x?

mikkonie · 2024-11-14T14:35:46Z

Workaround for PAM auth failing:

Use old version of our Docker container (4.2.11_1.5.0)
Set IRODS_AUTHENTICATION_SCHEME to PAM (ONLY for the Davrods container!)
Run iadmin set_grid_configuration authentication password_min_time 3600 on the server to avoid TTL error (see here for more)

It would seem there is something wrong in the new version of the image I'm building. I need to still investigate that further, but at least we have a workaround.

HOWEVER: with this setup, ticket URLs still fail with HTTP 500. For that, see #8.

mikkonie · 2024-11-14T15:50:36Z

Alright soooo.. Turns out this is the same password_min_time issue also in the new Docker image. It just seems logging is somehow broken in the new image, so I never see the PAM_AUTH_PASSWORD_INVALID_TTL error in the client connection.

Next steps:

Fix logging
Fix hardcoded value in Davrods to accept larger values for password_min_time
- See PAM auth not working since irods upgrade to 4.3.X UtrechtUniversity/davrods#34
- In src/config.c, replace .rods_auth_ttl = 1 with an appropriate value
Continue looking into ticket URLs and other subtasks

mikkonie · 2024-11-15T10:58:44Z

Hardcoded password length limit fixed. Still looking into logging problems and anonymous ticket access failing with CAT_INVALID_USER.

mikkonie · 2024-11-15T12:28:07Z

Logging partially fixed. I can see davrods errors, but iRODS client errors are still not logged as they were in the previous Docker image build..

mikkonie · 2024-11-15T12:58:51Z

Logging fixed. The solution was to add the following lines under <VirtualHost>:

ErrorLog /path/to/your/davrods.error.log
LogLevel {{ DAVRODS_LOG_LEVEL }}

Then, by setting LogLevel to debug, iRODS client errors are also displayed. Not sure why this requires debug now as it previously didn't, but hey.

mikkonie · 2024-11-15T13:16:46Z

Done except for #8 which I'll handle in another ticket, because it may not be actually related to this upgrade..

mikkonie mentioned this issue Feb 1, 2023

Update taskflow and iRODS functionality for iRODS 4.3 bihealth/sodar-server#1592

Closed

mikkonie mentioned this issue Oct 15, 2024

Upgrade to davrods-docker v4.3.3_1.5.1-1 bihealth/sodar-docker-compose#63

Closed

4 tasks

mikkonie self-assigned this Oct 15, 2024

mikkonie added feature New feature or request environment Issues regarding dependencies, CI, deployment etc. and removed feature New feature or request labels Oct 15, 2024

mikkonie added this to the 4.3.x-1 milestone Oct 15, 2024

mikkonie mentioned this issue Oct 22, 2024

Custom DAVRODS_AUTH_NAME message not showing up in WebDAV browser login #7

Open

mikkonie added a commit that referenced this issue Nov 6, 2024

update to ubuntu and irods 4.3 (wip) (#3, #6)

4adb6bd

mikkonie added a commit that referenced this issue Nov 8, 2024

update dockerfile, entrypoint and templates (#3)

ad8f7be

mikkonie changed the title ~~Upgrade to Davrods 4.3~~ Upgrade for iRODS 4.3 Nov 8, 2024

mikkonie added a commit that referenced this issue Nov 8, 2024

fix logging (#3)

cedf178

mikkonie added a commit that referenced this issue Nov 8, 2024

cleanup log output (#3)

2073d2c

mikkonie mentioned this issue Nov 13, 2024

PAM authentication fails with iRODS 4.3.3 UtrechtUniversity/davrods#40

Closed

mikkonie added the feature New feature or request label Nov 14, 2024

mikkonie mentioned this issue Nov 14, 2024

Ticket URLs failing #8

Closed

mikkonie added a commit that referenced this issue Nov 14, 2024

fix password_min_time error for pam auth (#3)

197e676

This was referenced Nov 15, 2024

Increase password length limit #4

Closed

Switch to using forked version of Davrods #9

Closed

mikkonie added a commit that referenced this issue Nov 15, 2024

fix logging (wip), update log files (#3)

767efef

mikkonie added a commit that referenced this issue Nov 15, 2024

add DAVRODS_LOG_LEVEL, update env vars and readme (#3)

c51ee3a

mikkonie added a commit that referenced this issue Nov 15, 2024

update docs, cleanup (#3)

67b7fff

mikkonie closed this as completed Nov 15, 2024

mikkonie added a commit that referenced this issue Nov 15, 2024

update for irods 4.3 and ubuntu, fix password length limit (#3, #4, #6)

d0234ce

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Upgrade for iRODS 4.3 #3

Upgrade for iRODS 4.3 #3

mikkonie commented Feb 1, 2023 •

edited

Loading

mikkonie commented Oct 15, 2024 •

edited

Loading

mikkonie commented Nov 8, 2024 •

edited

Loading

mikkonie commented Nov 11, 2024

mikkonie commented Nov 13, 2024 •

edited

Loading

mikkonie commented Nov 14, 2024 •

edited

Loading

mikkonie commented Nov 14, 2024 •

edited

Loading

mikkonie commented Nov 15, 2024

mikkonie commented Nov 15, 2024

mikkonie commented Nov 15, 2024

mikkonie commented Nov 15, 2024

Upgrade for iRODS 4.3 #3

Upgrade for iRODS 4.3 #3

Comments

mikkonie commented Feb 1, 2023 • edited Loading

Tasks

mikkonie commented Oct 15, 2024 • edited Loading

mikkonie commented Nov 8, 2024 • edited Loading

mikkonie commented Nov 11, 2024

mikkonie commented Nov 13, 2024 • edited Loading

mikkonie commented Nov 14, 2024 • edited Loading

mikkonie commented Nov 14, 2024 • edited Loading

mikkonie commented Nov 15, 2024

mikkonie commented Nov 15, 2024

mikkonie commented Nov 15, 2024

mikkonie commented Nov 15, 2024

mikkonie commented Feb 1, 2023 •

edited

Loading

mikkonie commented Oct 15, 2024 •

edited

Loading

mikkonie commented Nov 8, 2024 •

edited

Loading

mikkonie commented Nov 13, 2024 •

edited

Loading

mikkonie commented Nov 14, 2024 •

edited

Loading

mikkonie commented Nov 14, 2024 •

edited

Loading