sftp server: handle_stat: cannot stat

[clubh]

The multipass log file (/Library/Logs/Multipass/multipassd.log) is suddenly exploding with gigabytes of entries like:

It appears like PHP is looping through include_paths and all failures to stat a file via sftp are logged.

Any idea how to suppress or disable this logging ?

Logs
[2021-08-18T13:53:46.493] [error] [sftp server] handle_stat: cannot stat '/Users/clu/www/phplib/file.class.php': no such file
[2021-08-18T13:53:46.493] [error] [sftp server] handle_stat: cannot stat '/Users/clu/www/project/file.class.php': no such file

Additional info

• macOS
• multipass 1.7.0+mac

Name: localsrv
State: Running
IPv4: 192.168.64.7
Release: Ubuntu 16.04.7 LTS
Image hash: ef5bafec76cc (Ubuntu 16.04 LTS)
Load: 0.21 0.11 0.09
Disk usage: 7.9G out of 9.6G
Memory usage: 300.1M out of 2.0G
Mounts: /Users/clu/www => /www
UID map: 501:default
GID map: 20:default

[Saviq]

Hi @clubh, there's currently no way to do so, sorry.

You're right, we should reduce the severity of those messages, will let you know when there's a package available to test.

[surahman]

Hi @Saviq, I have had a quick look at the source code again, I have not delved into this part of the codebase as of yet. What are your thoughts?

My preference would be to handle the preferred log_level globally by having a setting that is sticky. This would have the side-effect of limiting the granularity of the log_level for all the log statements.

There is a data member in include/logger.h:logging_level which is set to Level::error. I do not see any methods to change this value. standard_logger seems to be checking against this logging_level. Logger is a base class for both multiplexing_logger and standard_logger, so it would probably be prudent to add a setter/getter to the Logger class to allow logging_level adjustments.

I believe there should be:

• A global base_log_level saved in the Daemon's settings file. This would make the log_level persistent in the event of a Daemon restart.

• The Client will need to be able to set the base_log_level on the Daemon (CLI command and an RPC?).

• Scope the log levels to All[Debug[Info[Warn[Error[None]]]]]. Since these are enums (include\level.h::Level) a check using inequality operators can be performed to apply scoping of the event severity. I believe it would be helpful to receive Error notifications even if you have the level set to Warn etc. I believe that by the way it is setup now there is a ceiling level cap to error.

• Check the base_log_level against the message's log_level:

  if (log_level >= base_log_level)
      // display log message.

  As stated above, this appears to be happening in mpl::StandardLogger::log already and will need to be handled in mpl::MultiplexingLogger::log.

• There would need to adjustments to: include/level.h, logger.[h|cpp], log.[h|cpp] (?),multiplexing_logger.[h|cpp], standard_logger.[h|cpp].

[Saviq]

@surahman hey, thanks for looking at this. It's actually just a case of changing the level of the different log calls as appropriate.

This particular case is here:

multipass/src/sshfs_mount/sftp_server.cpp

Lines 945 to 946 in 69aeaeb

	mpl::log(mpl::Level::error, category,
	fmt::format("{}: cannot stat \'{}\': no such file", __FUNCTION__, filename));

This one should probably be dropped to trace level (the levels are defined in multipass/logging/level.h). It would make sense to review all the other uses in this file. If the status of the failed operation is forwarded through the SFTP connection, there's likely no point in logging an error there. trace level makes sense there for debugging of the SFTP server itself.

The level at which the daemon is logging is set via the --verbosity option (and we log at debug by default to have as much context as possible for bug reports).

The client also has -v that raises the logging level, and it also logs daemon messages while it's running.

[surahman]

Thank you @Saviq, I completely forgot about the verbosity flags on the Client which I had seen in the test batteries 🤦. I will review and downgrade all the forwarded error messages to trace and have a look at all other log statements as well.

[clubh]

Would downgrading to 1.6.2 solve this issue? Right now I am unable to use Multipass due to the excess logging.

[Saviq]

@clubh no, but you can try the package that will be published at the PR (#2207). I just triggered a build, will let you know when it's ready.

[Saviq]

@clubh you can download the package from here:

https://github.com/canonical/multipass/runs/3399923322

[clubh]

@Saviq Works perfectly, thanks.

[antego]

@Saviq the macos build is not accessible anymore, it says

<?xml version="1.0" encoding="UTF-8"?>
<Error><Code>AccessDenied</Code><Message>Access Denied</Message><RequestId>7ZVGE6P78B14FS4N</RequestId><HostId>tSaI5fEtuXsl7vlWAWHQMjwJ/PCG379w135t7uZQJ/MWnx8Lo6KOzRiNYEiAgL3CZYMfcYY2mlc=</HostId></Error>

Is there any other way of getting the package with the fix?