Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Implement a bridge from the rust log crate to android. #472

Merged
merged 18 commits into from Jan 23, 2019

Conversation

Projects
None yet
3 participants
@thomcc
Copy link
Contributor

commented Dec 14, 2018

Ugh, this finally works. It's extremely annoying to debug, and for a lot of it the best way was "scatter std::process::exit(line!() as i32) around and see what gets hit".

Issues:

  • This is totally useless when not megazording (as a result, I didn't update build scripts to add :ac-log-library to various places, although maybe I should?). There's no way to do it such that it would work outside of a megazord context. When testing this locally I just manually megazorded it into logins, but we should figure it out.

  • It has the same restriction as the underlying rust log crate: you may only initialize it once. Unlike the rust log crate, you can de-initialize it. We could drop this at the cost of higher memory usage and removing a way to free the additional thread used to call the callbacks internally.

  • Along the same lines, it's existence means we probably can't log to logcat at the same time. Or if we do we need to do it from this lib. That is, using android_logger will prevent us from using this lib, as rust's log crate can only be initialized once.

  • It doesn't let the user control the max log level (turning this level on to Trace, which we do, impacts performance negatively). This should be fixed before landing.

  • It's fairly subtle code. The obvious ways of writing this had problems, and I have a 'TODO explain' for explaining it. (I'll get that sorted out tomorrow.)

  • Debugging is very hit or miss inside java code called from rust code. Sometimes breakpoints are skipped, sometimes things break terribly, often the process just crashes instead of hitting the breakpoint. Sometimes it works though, which is nice.

    We could probably get around this by doing a similar trick to what we do in rust. E.g. spin up a java thread that reads from a concurrent queue, and call the callback on that thread. The downside of this is that we now have 2 threads (one rust, one java) that exist just to send around log messages. On mobile devices that's not great.

  • I don't have 100% confidence that it's correct/safe. Probably more like 90%. It seems correct, but much of this took reading JNA's code, manual testing, etc. I'm not willing to rule out the possibility that something still gets called on the wrong thread and the world blows up, or that something gets GCed that rust code relies on and, again, the world blows up. I think the way to address this will be manual testing.

  • If something fails when destroying the adaptor, we abort the process. This is the only safe option, since otherwise there's no way for us to prevent things from calling a stale function pointer, which is extremely unsafe.

Anyway, before landing I want to:

  • Expose setting max_level
  • Delete the use of android_logger from various places (or figure out what we want to do here)
  • Add it to the megazords
  • Finish the TODO comment about explaining why we have two channels and an atomic flag for synchronizing.

Fixes #205

@rfk

This comment has been minimized.

Copy link
Member

commented Dec 17, 2018

Thanks for pushing through on this @thomcc!

If I may suggest, please also add a brief high-level overview of the design choices made for this module, e.g. "We spawn a rust thread and it does ABC for XYZ reasons". I'm not entirely sure what the right place for such commentary is (module-level readme? docstring comments at top of file?) but we should try to establish some shared habits for capturing such context.

@ncalexan ncalexan self-requested a review Jan 2, 2019

@thomcc thomcc force-pushed the ac-log-adapter branch 2 times, most recently from 862a11a to f251e66 Jan 5, 2019

@thomcc

This comment has been minimized.

Copy link
Contributor Author

commented Jan 5, 2019

This is ready for review now. It will temporarily make debugging more difficult (due to taking out the existing android_logger usage), so perhaps it shouldn't land until after the next major version (e.g. the one in #507).

(OTOH it will fix some of the performance issues @grigoryk had been mentioning, so maybe that's a mixed bag)

@ncalexan
Copy link
Member

left a comment

Generally I'm very impressed with this PR: you more or less found the same contours in the problem space, and you pushed through a solution. Bravo!

However, I'd like to jointly discuss, and potentially iterate on, several things:

  1. Fundamentally, I'm uneasy off-loading a bunch of JVM book-keeping to JNA. I don't trust JNA to get it right ('cuz I tried to get it right, and it's finicky!) and I don't trust us to use JNA in just the right way (for the same reasons). So I'd really prefer to bite the bullet and keep a JVM handle, JNI references, etc, ourselves. Pretty much everywhere you talk about "don't GC this..." or "I can't release this...", that's a place where we can (with some pain) actually do the right thing. (I started working through some of these bits, although I lost that work; and I'm happy to work with you to do what I'm talking about.) N.b., JNA makes it possible to get a JNIEnv* first argument, which is needed to make the whole dance possible -- look for CVT_JNIENV in JNA.

  2. I also came to the conclusion that logging from arbitrary native threads was frustrating, 'cuz attaching JVM threads is expensive; and that a dedicated JVM logging thread was a reasonable approach. I'd really prefer that thread to be created and managed on the JVM side of the house. I don't know how to integrate with the JVM parking lot at a low-level; I think it's not feasible. But it's definitely feasible to notify objects, etc; and to push things into JVM queues, etc; so I think we can move a lot of the thread management bits up to the JVM level and simplify our lives a little. There's no reason that we can't have a long-running/infinitely-looping JVM thread that's always in Rust code... at least, not that I'm aware of.

  3. You accept an arbitrary callback; I hard-coded to the a-c logging functions. Your solution is more flexible and makes testing more pleasant, but it's harder to know the lifetime of such a callback function. An arbitrary function at top-level doesn't really exist to the JVM, at least not pre-lambdas and Java 1.8 (and Android is mostly pre-Java 1.8); does it map to a Java static function? I might want to scope this down to only the a-c logging functions because it's easier to reason about the underlying objects and lifecycles. On the other hand, if we get a JNI reference to the function and hold on to it, it should never go out of scope -- that's pretty fundamental to the whole system.

Overall, bravo -- and sorry for the slow review. Lots to think about here. Immediate next steps are for your to digest my response, see how you feel about these issues, and then for us to Vidyo later this week.

👏


apply from: "$rootDir/publish.gradle"
ext.configurePublish(
'mozilla.appservices.rustlog',

This comment has been minimized.

Copy link
@ncalexan

ncalexan Jan 9, 2019

Member

Any reason to make this "rustlog" and not be consistent with "ac_log"?

This comment has been minimized.

Copy link
@thomcc

thomcc Jan 10, 2019

Author Contributor

From the rust side it's about hooking logging up to android components, but from the android components side it's about hooking rust logging up, so it seems weird to name it ac_log.

Arguably both names should have ac and rust in them or something though.

This comment has been minimized.

Copy link
@ncalexan

ncalexan Jan 23, 2019

Member

Make this "org.mozilla.appservices" and "rustlog", please. We want to standardize on that Maven groupId, and this will help.

androidTestImplementation 'com.android.support.test.espresso:espresso-core:3.0.2'
}

afterEvaluate {

This comment has been minimized.

Copy link
@ncalexan

ncalexan Jan 9, 2019

Member

Wow, these boilers are well and truly plated!

testImplementation 'org.mockito:mockito-core:2.21.0'

androidTestImplementation 'com.android.support.test:runner:1.0.2'
androidTestImplementation 'com.android.support.test.espresso:espresso-core:3.0.2'

This comment has been minimized.

Copy link
@ncalexan

ncalexan Jan 9, 2019

Member

You really want Espresso for this? I doubt we want it for anything in a-s.

This comment has been minimized.

Copy link
@thomcc

thomcc Jan 10, 2019

Author Contributor

It was copied from how I got tests to work for logins, but I don't remember if this was necessary there or if it just came along when copying the test stuff from elsewhere (perhaps the mentat android test code's build.gradle)

}

afterEvaluate {
// The `cargoBuild` task isn't available until after evaluation.

This comment has been minimized.

Copy link
@ncalexan

ncalexan Jan 9, 2019

Member

I should just fix ncalexan/rust-android-gradle#29 so we don't need this. Thanks for the nudge.

Show resolved Hide resolved components/ac_log/android/src/main/AndroidManifest.xml Outdated
Show resolved Hide resolved ...g/android/src/main/java/mozilla/appservices/rustlog/LibRustLogAdapter.kt Outdated
Show resolved Hide resolved components/ac_log/src/lib.rs Outdated
Show resolved Hide resolved components/ac_log/src/lib.rs Outdated
Show resolved Hide resolved components/logins/Cargo.toml
Show resolved Hide resolved ...ents/ac_log/android/src/test/java/mozilla/appservices/rustlog/LogTest.kt Outdated

@thomcc thomcc force-pushed the ac-log-adapter branch 5 times, most recently from c5fb4de to 4d18535 Jan 10, 2019

@ncalexan
Copy link
Member

left a comment

@thomcc and I have talked about many aspects of this on Slack, and Thom has made some great changes. I'm pretty confident this is a robust implementation. Immediate next steps:

  1. @thomcc to consider filtering logs. In my WIP I used https://docs.rs/env_logger/0.6.0/env_logger/filter/index.html -- Thom, does that seem like a thing we could use to control the log levels from the JVM side? Or do you have other things you think we should do?

  2. /me to test locally: try to wire it into a consumer and see how it actually works in the wild.

  3. a final pass to name the crate/project and get it into the megazords correctly.

@thomcc

This comment has been minimized.

Copy link
Contributor Author

commented Jan 14, 2019

Hmm, Do we need log filtering beyond filtering on level?

I'd rather implement something custom than reuse env_logger due to code size concerns (the regex dep it takes is both large, and not particularly useful for us)

@ncalexan

This comment has been minimized.

Copy link
Member

commented Jan 14, 2019

Hmm, Do we need log filtering beyond filtering on level?

I'd rather implement something custom than reuse env_logger due to code size concerns (the regex dep it takes is both large, and not particularly useful for us)

I don't feel particularly strongly about it, but my guess is that level will quickly get unhelpful. That is, I would expect to want debug/trace logs from logins sometimes, and debug/trace logs from places other times. Maybe the volume of such logs total across even a-s components is not so great that we couldn't filter at the JVM level? tokio and friends are super chatty, though.

I expect we'll want to grow some filtering pretty fast. How would you feel about extracting something like env logger's filter, sans regexp? What's your opinion here?

@thomcc

This comment has been minimized.

Copy link
Contributor Author

commented Jan 14, 2019

I don't feel particularly strongly about it, but my guess is that level will quickly get unhelpful. That is, I would expect to want debug/trace logs from logins sometimes, and debug/trace logs from places other times. Maybe the volume of such logs total across even a-s components is not so great that we couldn't filter at the JVM level? tokio and friends are super chatty, though.

They're a lot more chatty at trace level than at Debug/Info levels. They're relatively non-chatty compared to most things on android IME though, but I guess the AC stuff won't have quite as much coming in...

If the volume is a problem there are some pretty easy optimizations we can apply to make logging faster (right now no effort is made to minimize allocations of LogRecords on the rust side. These could be reused without a lot of additional work. We could also put a cutoff on log message length and eliminate their allocations all together).

I expect we'll want to grow some filtering pretty fast. How would you feel about extracting something like env logger's filter, sans regexp? What's your opinion here?

I don't have any issue with that. I'd sort of rather wait for the request for more log filtering options to come in before we implement it though. I suspect most users aren't going to go through the trouble of turning off logs from specific rust crates. That said, I also don't care that much and am willing to do this.

@ncalexan

This comment has been minimized.

Copy link
Member

commented Jan 14, 2019

I don't feel particularly strongly about it, but my guess is that level will quickly get unhelpful. That is, I would expect to want debug/trace logs from logins sometimes, and debug/trace logs from places other times. Maybe the volume of such logs total across even a-s components is not so great that we couldn't filter at the JVM level? tokio and friends are super chatty, though.

They're a lot more chatty at trace level than at Debug/Info levels. They're relatively non-chatty compared to most things on android IME though, but I guess the AC stuff won't have quite as much coming in...

If the volume is a problem there are some pretty easy optimizations we can apply to make logging faster (right now no effort is made to minimize allocations of LogRecords on the rust side. These could be reused without a lot of additional work. We could also put a cutoff on log message length and eliminate their allocations all together).

There's a limit on log message length from Android itself. It used to be low -- 512b, maybe 1024b -- and now is comically high -- 32kb sticks in my mind. But no, it's about 5kb: http://androidxref.com/4.4.4_r1/xref/system/core/include/log/logger.h#64

So picking an arbitrary value above that is fine.

I expect we'll want to grow some filtering pretty fast. How would you feel about extracting something like env logger's filter, sans regexp? What's your opinion here?

I don't have any issue with that. I'd sort of rather wait for the request for more log filtering options to come in before we implement it though. I suspect most users aren't going to go through the trouble of turning off logs from specific rust crates. That said, I also don't care that much and am willing to do this.

OK, that's fair. Let's leave it at levels for now, see how it works in the wild.

@thomcc

This comment has been minimized.

Copy link
Contributor Author

commented Jan 14, 2019

I don't feel particularly strongly about it, but my guess is that level will quickly get unhelpful. That is, I would expect to want debug/trace logs from logins sometimes, and debug/trace logs from places other times. Maybe the volume of such logs total across even a-s components is not so great that we couldn't filter at the JVM level? tokio and friends are super chatty, though.

They're a lot more chatty at trace level than at Debug/Info levels. They're relatively non-chatty compared to most things on android IME though, but I guess the AC stuff won't have quite as much coming in...
If the volume is a problem there are some pretty easy optimizations we can apply to make logging faster (right now no effort is made to minimize allocations of LogRecords on the rust side. These could be reused without a lot of additional work. We could also put a cutoff on log message length and eliminate their allocations all together).

There's a limit on log message length from Android itself. It used to be low -- 512b, maybe 1024b -- and now is comically high -- 32kb sticks in my mind. But no, it's about 5kb: http://androidxref.com/4.4.4_r1/xref/system/core/include/log/logger.h#64

So picking an arbitrary value above that is fine.

Ah, thats high enough that doing inline allocation (which is the only way to avoid allocations all together) is unreasonable. Something like, 256b or so would be a limit where something like that would be practical.

With a high limit like that (really anything higher than, say, 256b, which is still pretty long for a log message IMO) we'd still want to heap allocate the body of the messages, which means if we want to optimize this, pooling them (well, using a free list) would be the best option. This would require another channel for sending the message back when it's no longer being used so that its memory can be reused. I have a patch that did this (although it certainly no longer applies cleanly), but I decided that we really need some benchmarks before anything like that.

@thomcc

This comment has been minimized.

Copy link
Contributor Author

commented Jan 15, 2019

Following discussion in slack, we're not going to filter logs until someone asks for it. It seems unlikely that any consumers are going to look up the set of crates they want to filter out.

One thing I do need to do still, however, is to update the header comments in crate.

@thomcc thomcc force-pushed the ac-log-adapter branch 2 times, most recently from 4745359 to ab048ca Jan 16, 2019

@ncalexan

This comment has been minimized.

Copy link
Member

commented Jan 17, 2019

Coming back to this after testing. This is looking very good. I have a few requests:

  • Can we figure out how not to include file paths in the logs? That's going to bloat our .so size a great deal, and it's just not that helpful. E.g., I see:
hyper::client::pool: /Users/nalexander/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.20/src/client/pool.rs@422: pooling idle connection for "https://sync-524-us-west-2.sync.services.mozilla.com"
  • Can we make the .so name standard, i.e., libac_log_ffi.so or librustlog_ffi.so, like all the others? Nothing depends on this right now but I'd prefer they all look like libFOO_ffi.so, so that when we do want to filter it's lib*_ffi.so.
  • Can we get a rebased push so that I can see the green? I don't quite understand how the test targets are going to work. The new code defaults the logging on, which uses android_logger, which under the hood invokes liblog.so functions... and those aren't present in a Robolectric environment. I expect that to fail, but if it passes I really want to understand why it passes :)
  • When integrating against Lockbox (which was very easy), I needed to manually convert the i32 that the Rust log adapter gives me to an a-c Log.Priority. No biggie:
+        RustLogAdapter.enable { level, tagStr, msgStr ->
+            val l = when (level) {
+                2 -> Log.Priority.DEBUG
+                3 -> Log.Priority.DEBUG
+                4 -> Log.Priority.INFO
+                5 -> Log.Priority.WARN
+                6 -> Log.Priority.ERROR
+                else -> Log.Priority.ERROR
+            }
+            Log.log(l, tagStr, null, msgStr)
+            true
+        }

But it's a pain. I understand the desire (really, hard requirement) to not have a compile-time dependency on anything from a-c, but can we do better? Maybe we could either have a helper that does this conversion in Log.Priority in a-c; or maybe we can expose a method with the right signature there?

@thomcc thoughts on these points?

@thomcc

This comment has been minimized.

Copy link
Contributor Author

commented Jan 18, 2019

Pretty sure the file paths are already present in the .so file. We just get passed a log record which has them, we don't have any control over what's inside it really. Anyway, I'll remove it from the log, it's probably redundant given the fact that we include the module already.

and those aren't present in a Robolectric environment

That dependency is under #[cfg(target_os = "android")], which also isn't present in a Robolectric environment. (But of course I will get a green push up).

Will respond to others tomorrow.

@thomcc thomcc force-pushed the ac-log-adapter branch 3 times, most recently from a357306 to ab14e96 Jan 18, 2019

@thomcc

This comment has been minimized.

Copy link
Contributor Author

commented Jan 19, 2019

I understand the desire (really, hard requirement) to not have a compile-time dependency on anything from a-c, but can we do better?

I'll PR https://github.com/thomcc/android-components/tree/rustlog after this lands and has a release number.

thomcc added some commits Nov 19, 2018

Use "Direct Mapping" for calling into the logger.
We don't need the flexibility of the other approach here, and this is
many times faster (and given how much log spam we can get sometimes,
that matters). It wasn't clear to me how to make a kotlin
`@JvmStatic init` so this moves LibRustLogAdapter to Java as well.
Make test check that the GC can still collect our background threads …
…(but won't do so until we're done using them)
Ensure we still have logs available in non-megazord contexts
This is done by exposing a function from each .so that enables using the
`android_logger` crate, and automatically calling this after loading the
`.so` file if we aren't a megazord.
@ncalexan
Copy link
Member

left a comment

I noticed a few more small things, but overall this is looking great. Well done!

Show resolved Hide resolved components/rc_log/Cargo.toml
Show resolved Hide resolved CHANGELOG.md Outdated
Show resolved Hide resolved CHANGELOG.md
Show resolved Hide resolved gradle-plugin/src/main/kotlin/mozilla/appservices/AppServicesExtension.kt Outdated
Show resolved Hide resolved ..._log/android/src/main/java/mozilla/appservices/rustlog/RustLogAdapter.kt Outdated

apply from: "$rootDir/publish.gradle"
ext.configurePublish(
'mozilla.appservices.rustlog',

This comment has been minimized.

Copy link
@ncalexan

ncalexan Jan 23, 2019

Member

Make this "org.mozilla.appservices" and "rustlog", please. We want to standardize on that Maven groupId, and this will help.

thomcc added some commits Jan 23, 2019

@thomcc thomcc force-pushed the ac-log-adapter branch from 97e3833 to 68e468a Jan 23, 2019

@thomcc thomcc merged commit 0235e96 into master Jan 23, 2019

4 of 5 checks passed

Taskcluster (pull_request) TaskGroup: Pending (for pull_request.synchronize)
Details
ci/circleci: Check Rust formatting Your tests passed on CircleCI!
Details
ci/circleci: Rust tests - beta Your tests passed on CircleCI!
Details
ci/circleci: Rust tests - stable Your tests passed on CircleCI!
Details
ci/circleci: Sync integration tests Your tests passed on CircleCI!
Details

@thomcc thomcc deleted the ac-log-adapter branch Jan 23, 2019

jrconlin added a commit that referenced this pull request Jan 30, 2019

Implement a bridge from the rust log crate to android. (#472)
* Implement a bridge from the rust log crate to android.

* Ensure we still have logs available in non-megazord contexts

* Changelog entry

* Gradle plugin bump to 0.3.0

* Android version bump to v0.14.0
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.