add conditional smb trace logging for debug purposes #25758

Merged
merged 1 commit into from Aug 14, 2016

Projects

None yet

4 participants

@butonic
Member
butonic commented Aug 10, 2016

To debug windows network drive issues we need traces. Unfortunately, installing xdebug is not always an option. being able to swith it on via a command line switch is a big win. We did it for 8.2 while debugging a problem. This PR brings the logging part to master.

The leave() and swallow() could be pulled up to the Common Storage or moved to the ILogger api. For now, having it in smb should suffice. We can move it to core if it turns out useful in other places.

cc @felixboehm @DeepDiver1975

@mention-bot

@butonic, thanks for your PR! By analyzing the annotation information on this pull request, we identified @icewind1991, @blizzz, @jvillafanez and @Xenopathic to be potential reviewers

@butonic butonic added this to the 9.2 milestone Aug 10, 2016
@DeepDiver1975 DeepDiver1975 and 1 other commented on an outdated diff Aug 10, 2016
apps/files_external/lib/Lib/Storage/SMB.php
} catch (ConnectException $e) {
- throw new StorageNotAvailableException($e->getMessage(), $e->getCode(), $e);
+ throw $this->leave(__FUNCTION__, new StorageNotAvailableException(
@DeepDiver1975
DeepDiver1975 Aug 10, 2016 Member

Can we leave the throw statement as is and add the leave() call right before is like this:

$this->leave(__FUNCTION__);
throw new StorageNotAvailableException($e->getMessage(), $e->getCode(), $e);
@butonic
butonic Aug 11, 2016 Member

no, because these exceptions are sometimes swallowed, eg. by the availability wrapper: https://github.com/owncloud/core/blob/master/lib/private/Files/Storage/Wrapper/Availability.php#L53.

leave() detects an exception and also logs a stacktrace which is the most interesting thing when debugging this.

@DeepDiver1975
DeepDiver1975 Aug 11, 2016 Member

Then:

$e = new exception
This->leave(function, $e)
Throw $e
@butonic
butonic Aug 11, 2016 Member

we could do that but it only adds an unnecessary variable.

@DeepDiver1975
DeepDiver1975 Aug 11, 2016 Member

and adds more structure to the code. ๐Ÿ˜‰

@jvillafanez jvillafanez commented on an outdated diff Aug 10, 2016
apps/files_external/lib/Lib/Storage/SMB.php
@@ -64,6 +65,9 @@ class SMB extends \OC\Files\Storage\Common {
protected $statCache;
public function __construct($params) {
+ $loggedParams = $params;
+ $loggedParams['password'] = '***removed***';
@jvillafanez
jvillafanez Aug 10, 2016 Contributor

Maybe it's better to substitute the password only if it's set. I don't think it's too bad to the password empty if it's really empty. Anyway, if somehow the password isn't sent this would show wrong information.

@jvillafanez jvillafanez commented on the diff Aug 10, 2016
apps/files_external/lib/Lib/Storage/SMB.php
case 'w':
case 'wb':
$source = $this->share->write($fullPath);
- return CallBackWrapper::wrap($source, null, null, function () use ($fullPath) {
+ $result = CallBackWrapper::wrap($source, null, null, function () use ($fullPath) {
@jvillafanez
jvillafanez Aug 10, 2016 Contributor

The other CallBackWrapper below returns directly

@jvillafanez jvillafanez commented on the diff Aug 10, 2016
apps/files_external/lib/Lib/Storage/SMB.php
} catch (Exception $e) {
- return false;
+ $this->swallow(__FUNCTION__, $e);
+ }
+ return $this->leave(__FUNCTION__, $result);
+ }
+
+
+ /**
+ * @param string $message
+ * @param int $level
+ * @param string $from
+ */
+ private function log($message, $level = Util::DEBUG, $from = 'wnd') {
+ if (\OC::$server->getConfig()->getSystemValue('wnd.logging.enable', false) === true) {
@jvillafanez
jvillafanez Aug 10, 2016 Contributor

Is it worthy to cache the config value?

@butonic
butonic Aug 11, 2016 Member

getSystemValue() accesses the config array which is already in memory. Not much to gain by caching it in this class. It would however be cleaner to use DI for the config instead of using \OC::$server.

Regarding performance I would like to see if assembling the message in a closure could save some cycles. Sometimes (not only in this class) we use quite some logic to build a message that is never logged because the log level is not set to debug or info. But that is an exercise in premature optimization IMO.

@jvillafanez
jvillafanez Aug 11, 2016 Contributor

Agreed ๐Ÿ‘

@jvillafanez
Contributor

reviewed

@butonic
Member
butonic commented Aug 11, 2016

@jvillafanez @DeepDiver1975 thx for the quick review! I updated the PR accordingly.

@jvillafanez jvillafanez commented on the diff Aug 11, 2016
apps/files_external/lib/Lib/Storage/SMB.php
@@ -64,6 +65,13 @@ class SMB extends \OC\Files\Storage\Common {
protected $statCache;
public function __construct($params) {
+ $loggedParams = $params;
+ // remove password from log if it is set
+ if (!empty($loggedParams['password'])) {
@jvillafanez
jvillafanez Aug 11, 2016 Contributor

I'd also check that the 'password' key exists, so the log won't interfere with the normal flow. If somehow the 'password' key is missing, I guess the log below won't be shown and the expected exception won't be thrown.

@jvillafanez
jvillafanez Aug 11, 2016 Contributor

I guess it's fine. I'd add a comment because it's confusing for me: I'd expect the code to explode trying to access to a missing index.

If there are no more pending changes let's go with this as it is. Don't bother to add a new commit just for adding a comment ๐Ÿ˜„

@butonic
butonic Aug 11, 2016 Member

empty() works fine for unset keys however there is kind of a false positive when checking with empty(): it will return true when checking an array key that has been set to 0 or "0". But I can live with that.

@butonic
Member
butonic commented Aug 11, 2016

reviews are in. give me your ๐Ÿ‘ pls

@jvillafanez @felixboehm @DeepDiver1975

@jvillafanez
Contributor

๐Ÿ‘

@butonic butonic add conditional smb trace logging for debug purposes
2d1d97b
@butonic
Member
butonic commented Aug 12, 2016 edited

made @DeepDiver1975 happy, lets see if jenkins is still happy

@butonic
Member
butonic commented Aug 12, 2016

needs backport to 9.1 and 9.0

@DeepDiver1975
Member

@butonic scrutinizer is reporting 24 new issues - mind taking a look? THX

@DeepDiver1975
Member

I'll kick jenkins

@butonic
Member
butonic commented Aug 14, 2016 edited

Scrutinizer does not know where to find the used exceptions. Dunno why he finds those problems now ... not an issue IMO.

@DeepDiver1975
Member

๐Ÿ‘

@DeepDiver1975 DeepDiver1975 merged commit b5bb06a into master Aug 14, 2016

3 of 4 checks passed

continuous-integration/jenkins/pr This commit has test failures
Details
Scrutinizer 24 new issues, 3 updated code elements
Details
continuous-integration/travis-ci/pr The Travis CI build passed
Details
licence/cla Contributor License Agreement is signed.
Details
@DeepDiver1975 DeepDiver1975 deleted the smb_tracing branch Aug 14, 2016
@blizzz blizzz referenced this pull request in nextcloud/server Aug 29, 2016
Closed

add conditional smb trace logging for debug purposes #1150

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment