jakeheis / Shout

SSH made easy in Swift
MIT License
357 stars 103 forks source link

Execute method memory leak #44

Closed levidhuyvetter closed 4 years ago

levidhuyvetter commented 4 years ago

Hi Jake,

I've run into a problem when using one certain command ("/usr/local/bin/mysql.server start"). When using this command in terminal the output is:

Starting MySQL\n
.. SUCCESS! \n

When I use this command with shout, the execute method never returns. I've tried digging a bit deeper and found that the problem might be with how this snippet of code is reading the string from memory:

let str = data.withUnsafeBytes { (pointer: UnsafePointer<CChar>) in
    return String(cString: pointer)
}

With most commands I execute using shout this pointer points to a C string in memory that is terminated by a \0 byte, but with this particular command the first line Starting MySQL\n is not null terminated in memory:

Screenshot 2020-06-04 at 20 18 01

As a result, any data in memory after the data I need, until the first \0 byte gets included in the string:

Screenshot 2020-06-04 at 20 18 42

In this case it's just the apple but I've seen it have anything from random characters to names of cocoa classes included in the string.

I've also had the operating system pop up alerts about memory leaks when this happens and my guess would be that this memory leak is causing channel.readData() to never return for some reason so the .done case in execute method is never reached.

When I looked at this code my first thought was to create the string from the data with String(data: data, encoding: .utf8) but this might cause problems assuming an encoding of utf8 so I'd be happy to hear you thoughts on this.

Is the data returned by the channel supposed to be null terminated?

If it is, any ideas on why it is not in this particular case? If it is not, is there a way we can change this code to account for this?

As a side note: The command /usr/local/bin/mysql.server stop which has an almost identical response in terminal does not cause this problem and seems to be always null terminated in my case.

levidhuyvetter commented 4 years ago

Hi Jake,

I've discovered why the command was not returning and it turns out to be a problem with the mysql startup script.

I'm not closing the issue just yet in case you want to investigate why this was causing memory leaks. If not feel free to close it.

If you need to reproduce this, the line in the mysql.server script that was causing it not to return is this one:

$bindir/mysqld_safe --datadir="$datadir" --pid-file="$mysqld_pid_file_path" $other_args >/dev/null &

Something weird is going on in mysqld_safe keeping the stderr busy, redirecting it to stdout to be discarded together seems to do the trick:

$bindir/mysqld_safe --datadir="$datadir" --pid-file="$mysqld_pid_file_path" $other_args >/dev/null 2>&1 &

cyrusingraham commented 4 years ago

I was just going to open an issue for the same problem. We are running into this with multiple system binaries outputs.

levidhuyvetter commented 4 years ago

I am running into an issue in the same place. It appears this is assuming a null terminated string but the buffer is not null terminated.

Do you have examples of commands where this happens? The code has a bunch of deprecated withUnsafeBytes and dangling pointer warning, not sure if this has anything to do with it. I've tried taking them all out but my limited knowledge on how to do it properly instead was causing even stranger output.

cyrusingraham commented 4 years ago

The place where we are seeing the most crashes due to this when running log show --style json but /usr/bin/unzip is also problematic.

jakeheis commented 4 years ago

I believe String(data: data, encoding: .utf8) may partially fix the problem -- encoding is not a problem, as String(cString: pointer) assumes UTF-8 encoding anyway. My fear is that this will not work on the last line of text with a terminating null byte at the end, as using String(data:) will interpret this as a character and not as a terminator.

For example if the server sends "hello world" with a null byte terminator, using String(cString:) results in the string "hello world" as expected, while I believe using String(data:) would result in "hello world\0". Granted there is no comment in the code for why I didn't just use String(data:), but I'm guessing this is the reason.

This is definitely an issue that should be resolved, I'm just not entirely sure how to resolve it. Will look into this more.

levidhuyvetter commented 4 years ago

The place where we are seeing the most crashes due to this when running log show --style json but /usr/bin/unzip is also problematic.

Just had a go at unzip with a 2.5GB zipped folder and wasn't able to reproduce it. Seems to be properly terminated in memory although I'm not sure if that was on purpose or if there just happened to be a \0 byte there.

In my case the mysql script was keeping the error output busy (although there seemed to be nothing on there).

While looking around I came across an article that mentioned libssh2_channel_read_ex going into a loop if something is writing excessive amounts to the error output. I temporarily solved my issue by redirecting the error output to /dev/null by putting 2>/dev/null after the command. This just discards any errors.

cyrusingraham commented 4 years ago

I created a pull request fixing the warnings. This does not address this issue but I assume the warnings should be fixed.

levidhuyvetter commented 4 years ago

I believe String(data: data, encoding: .utf8) may partially fix the problem -- encoding is not a problem, as String(cString: pointer) assumes UTF-8 encoding anyway. My fear is that this will not work on the last line of text with a terminating null byte at the end, as using String(data:) will interpret this as a character and not as a terminator.

For example if the server sends "hello world" with a null byte terminator, using String(cString:) results in the string "hello world" as expected, while I believe using String(data:) would result in "hello world\0". Granted there is no comment in the code for why I didn't just use String(data:), but I'm guessing this is the reason.

This is definitely an issue that should be resolved, I'm just not entirely sure how to resolve it. Will look into this more.

Hi Jake,

As for the conversion to string, this seems to work fine in my case:

let cstr:[UInt8] = [65,66,67,0]
let cdata = Data(cstr)
let str = String(data: cdata, encoding: .utf8)!
print(str)

But I've seen people converting Data -> String -> C-String -> String to get rid of null terminators:

let cstr2:[UInt8] = [65,66,67,0]
let cdata2 = Data(cstr2)
let str2 = String(cString: String(data: cdata2, encoding: .utf8)!.cString(using: .utf8)!)
print(str2)

As for the general problem, my guess is that memory leaks occur if there is excessive amounts of data being read or written. Perhaps when a buffer somewhere is overflowing and the unsafe reading of bytes is trying to read bytes that don't exist anymore.

I have limited knowledge when it comes to this kind of stuff so I might be wrong but perhaps it's time to get rid of the deprecated warnings by doing it the new way they're intended to be used?

cyrusingraham commented 4 years ago

I can confirm the changes in #46 fix the issue. I am able to consistently reproduce the problem running the command log show --style json --info --debug which returns a large amount of data dependent on the host. The environment I am testing with is consistently returning 9k-10k log messages.

levidhuyvetter commented 4 years ago

I've also reviewed the changes in PR #46 and they do fix the memory leak issue. Can someone link PR #46 to this issue so it may be closed once merged?

For completeness sake: This did not solve my original problem with the mysql script but I have posted on the MySQL Forums about this in case anyone is interested: https://forums.mysql.com/read.php?132,688122

levidhuyvetter commented 4 years ago

PR #46 was merged