NAS-129926 / 25.04 / Log when private methods are called via websocket connection

[themylogin]

No description provided.

[bugclerk]

Jira URL: https://ixsystems.atlassian.net/browse/NAS-129926

[themylogin]

http://jenkins.eng.ixsystems.net:8080/job/master/job/custom/786/

[themylogin]

Just in case Jenkins deletes my build:

Test Result (35 failures / +30)
api2.test_012_directory_service_ssh.test_08_test_ssh_ad
api2.test_030_activedirectory.test_enable_leave_activedirectory
api2.test_030_activedirectory.test_activedirectory_smb_ops
api2.test_030_activedirectory.test_account_privilege_authentication
api2.test_030_activedirectory.test_secrets_restore
api2.test_030_activedirectory.test_keytab_restore
api2.test_032_ad_kerberos.test_kerberos_keytab_and_realm
api2.test_032_ad_kerberos.test_kerberos_krbconf
api2.test_032_ad_kerberos.test_kerberos_nfs4
api2.test_032_ad_kerberos.test_kerberos_ticket_management
api2.test_035_ad_idmap.test_name_sid_resolution
api2.test_035_ad_idmap.test_backend_options[AD]
api2.test_035_ad_idmap.test_backend_options[AUTORID]
api2.test_035_ad_idmap.test_backend_options[LDAP]
api2.test_035_ad_idmap.test_backend_options[NSS]
api2.test_035_ad_idmap.test_backend_options[RFC2307]
api2.test_035_ad_idmap.test_backend_options[TDB]
api2.test_035_ad_idmap.test_backend_options[RID]
api2.test_035_ad_idmap.test_clear_idmap_cache
api2.test_035_ad_idmap.test_idmap_overlap_fail
api2.test_035_ad_idmap.test_idmap_default_domain_name_change_fail
api2.test_035_ad_idmap.test_idmap_low_high_range_inversion_fail
api2.test_040_ad_user_group_cache.test_check_for_ad_users
api2.test_040_ad_user_group_cache.test_check_for_ad_groups
api2.test_040_ad_user_group_cache.test_check_directoryservices_cache_refresh
api2.test_040_ad_user_group_cache.test_check_lazy_initialization_of_users_and_groups_by_name
api2.test_040_ad_user_group_cache.test_check_lazy_initialization_of_users_and_groups_by_id
api2.test_040_ad_user_group_cache.test_update_delete_failures[UPDATE]
api2.test_040_ad_user_group_cache.test_update_delete_failures[DELETE]
api2.test_usage_reporting.test_nfs_reporting
api2.test_435_smb_registry.test__test_aux_param_on_update
api2.test_435_smb_registry.test__test_aux_param_on_create
api2.test_simple_share.test__smb_simple_share_validation
api2.test_virt_002_instance.test_virt_instance_shell
api2.test_staticroutes.test_staticroute

No new/important failures, just the usual stuff (AD)

[themylogin]

middleware.log has entries like this

[2024/12/09 05:36:58] (WARNING) middlewared.process_message():278 - Private method 'disk.sed_unlock_all' called on a connection without private method call enabled
[2024/12/09 05:36:58] (WARNING) middlewared.process_message():278 - Private method 'disk.sync_all' called on a connection without private method call enabled

Those are called by our systemd units. There are ~900 calls in total, 300 of them being

[2024/12/09 08:26:54] (WARNING) middlewared.process_message():278 - Private method 'system.general.get_ui_urls' called on a connection without private method call enabled

The second is midcli, I can fix that. But the first... We use midcli to call these methods, but we don't want users to use midcli to call the same methods... Any suggestions? @anodos325 @yocalebo

[anodos325]

middleware.log has entries like this

[2024/12/09 05:36:58] (WARNING) middlewared.process_message():278 - Private method 'disk.sed_unlock_all' called on a connection without private method call enabled
[2024/12/09 05:36:58] (WARNING) middlewared.process_message():278 - Private method 'disk.sync_all' called on a connection without private method call enabled

Those are called by our systemd units. There are ~900 calls in total, 300 of them being

[2024/12/09 08:26:54] (WARNING) middlewared.process_message():278 - Private method 'system.general.get_ui_urls' called on a connection without private method call enabled

The second is midcli, I can fix that. But the first... We use midcli to call these methods, but we don't want users to use midcli to call the same methods... Any suggestions? @anodos325 @yocalebo

We can expand ConnectionOrigin object to include loginuid from /proc/<pid>/loginuid. This gets set by pam for interactive sessions now (via SSH and local console), but will be uninitialized if non-interactive ( 4294967295).

System-initiated calls to midcli / midclt will have uninitialized loginuid and can be omitted from logging if socket type if AF_UNIX.

We should always log calls to private endpoints on unix socket if they originate from uid 33 (www-data) even if loginuid is unitialized. IIRC this is how proxied hexos calls will appear.

[themylogin]

http://jenkins.eng.ixsystems.net:8080/job/master/job/custom/813/

[themylogin]

@anodos325 @yocalebo with these patches in place, tests log contains only

[2024/12/17 02:04:26] (WARNING) middlewared.process_message():278 - Private method 'system.dmidecode_info' called on a connection without private_methods enabled

and

[2024/12/17 03:45:02] (WARNING) middlewared.process_message():278 - Private method 'config.backup' called on a connection without private_methods enabled

I fixed the second one (it was hactl)

The second was made by crontab (by a coincidence). Any idea wrt to how should we handle that?

[anodos325]

The second was made by crontab (by a coincidence). Any idea wrt to how should we handle that?

We could probably ignore if the process is cron (can get from procfs), though perhaps we should be scheduling within middlewared itself rather than cron?

[yocalebo]

This is a large file to read into memory and then do a regex search on. I also don't like this approach. I'd rather remove entries from middlewared.mako (cron) and schedule them as @periodic