Closed Bug 1019816 Opened 10 years ago Closed 10 years ago

Developer option to store logcat to sdcard by shaking the phone

Categories

(Firefox OS Graveyard :: Gaia::System, defect)

x86
macOS
defect
Not set
normal

Tracking

(tracking-b2g:backlog)

RESOLVED FIXED
2.1 S4 (12sep)
tracking-b2g backlog

People

(Reporter: gwagner, Assigned: jhobin)

References

Details

(Keywords: dev-doc-complete, Whiteboard: [systemsfe])

Attachments

(8 files, 15 obsolete files)

46 bytes, text/x-github-pull-request
timdream
: review+
timdream
: feedback+
Details | Review
47.84 KB, text/x-log
Details
44.69 KB, text/x-log
Details
3.03 KB, text/plain
Details
778 bytes, text/plain
Details
1.27 KB, text/plain
Details
1.25 KB, text/plain
Details
36.12 KB, patch
gerard-majax
: review+
Details | Diff | Splinter Review
      No description provided.
feature-b2g: --- → 2.1
Adding people that were interested in this feature and may have an opinion on this :)
And on top of logcat, we should also dump the phone model, the gaia and gecko revisions and any other common information we need to understand in which conditions this is happening.
Assignee: hobinjk → jhobin
Attachment #8438037 - Flags: review?(anygregor)
Attached patch Gecko-side implementation (obsolete) — Splinter Review
Attachment #8438039 - Flags: review?(anygregor)
Functionality overview:
Upon the enabling of the logshake preference, Logshake polls for high-acceleration movements. Upon detecting one of these shakes, it sends a message (as an event) to shell which uses LogCapture.jsm to read in /dev/log/main (configurable at compile-time), a very strange and weird special device file which is only documented by its implementation in the kernel. Ideally it then receives an event back with the current log file's contents, which it then can save to disk.

There are unit tests of both the Gecko and Gaia sides of this equation but no integration tests yet.
Cool :).

We may want to read other files, however:
 - /dev/log/radio, /dev/log/system
 - /proc/kmsg
 - getprop output
 - device uptime, running processes, free memory
Comment on attachment 8438039 [details] [diff] [review]
Gecko-side implementation

Alex, want to do a first round of review? Forward to vivien afterwards for the shell.js changes.
Attachment #8438039 - Flags: review?(anygregor) → review?(lissyx+mozillians)
Comment on attachment 8438037 [details] [review]
Gaia-side implementation

Tim, can you take a look or forward to someone?
Attachment #8438037 - Flags: review?(anygregor) → review?(timdream)
(In reply to Gregor Wagner [:gwagner] from comment #8)
> Comment on attachment 8438037 [details] [review]
> Gaia-side implementation
> 
> Tim, can you take a look or forward to someone?

(In reply to Gregor Wagner [:gwagner] from comment #7)
> Comment on attachment 8438039 [details] [diff] [review]
> Gecko-side implementation
> 
> Alex, want to do a first round of review? Forward to vivien afterwards for
> the shell.js changes.

I made quite a few changes to support reading from /proc/kmsg and getting system properties. I was about to obsolete both attachments, in fact. I'll copy the review flags over to the new patch and pr.
Attached patch Gecko-side implementation (obsolete) — Splinter Review
Both attachments now refer to the multi-file version, which saves /dev/log/{system,main,radio,events} and /proc/{kmsg,meminfo,version}. If available, it also saves the current property database (usually getprop).
Attachment #8438039 - Attachment is obsolete: true
Attachment #8438039 - Flags: review?(lissyx+mozillians)
Attachment #8438788 - Flags: review?(lissyx+mozillians)
Important side-note: the Gecko patch adds the property_get_all function to libcutils in systemlibs.js. Currently there are no tests for libcutils's functionality (at least none a quick grep located), so I didn't add any tests of property_get_all, but this is a clear area where test coverage could be improved.
Comment on attachment 8438788 [details] [diff] [review]
Gecko-side implementation

Review of attachment 8438788 [details] [diff] [review]:
-----------------------------------------------------------------

Just a first round, I'll comment further after testing this on device.

::: dom/system/gonk/systemlibs.js
@@ +36,3 @@
>    try {
>      lib = ctypes.open("libcutils.so");
> +    libc = ctypes.open("libc.so");

I'm really wondering if we could not mke use of libcutils.so already. Looking at the Flame tree, I see some interesting stuff within system/core/libcutils/properties.c.

You can browse the code at https://android.googlesource.com/platform/system/core/+/android-4.0.4_r2.1/libcutils/properties.c.

Specifically, I see property_list() which seems to be already doing what you do with property_get_all() and that seems to be intended to be exposed and used. Looking at the getprop.c source code (which is the getprop binary we rely on the device), you can see this is making use of this property_list() function.

@@ +81,5 @@
> +  //      char name[PROP_NAME_MAX];
> +  //      unsigned volatile serial;
> +  //      char value[PROP_VALUE_MAX];
> +  //};
> +

What is this comment doing here ? I suspect it's documenting the format of what we are retrieving, but I'm not sure it's useful there and in this form.

@@ +89,5 @@
> +  let c_property_read = libc.declare("__system_property_read", ctypes.default_abi,
> +                                   ctypes.void_t,     // return: none
> +                                   ctypes.voidptr_t,  // non-null prop_info*
> +                                   ctypes.char.ptr,   // key
> +                                   ctypes.char.ptr);  // value

Isn't there a better way to retrieve those? Having to use symbols defined as '__' in libc smells like we are accessing stuff we should not access.

@@ +90,5 @@
> +                                   ctypes.void_t,     // return: none
> +                                   ctypes.voidptr_t,  // non-null prop_info*
> +                                   ctypes.char.ptr,   // key
> +                                   ctypes.char.ptr);  // value
> +

Empty changes

@@ +154,3 @@
>      }
>  
> +

Empty changes
Comment on attachment 8438037 [details] [review]
Gaia-side implementation

Overall looks very good except the detail like `bind()`. Please re-request for review when that parts are fixed.
Attachment #8438037 - Flags: review?(timdream) → feedback+
(In reply to jhobin from comment #5)
> Functionality overview:
> Upon the enabling of the logshake preference, Logshake polls for
> high-acceleration movements. Upon detecting one of these shakes, it sends a
> message (as an event) to shell which uses LogCapture.jsm to read in
> /dev/log/main (configurable at compile-time), a very strange and weird
> special device file which is only documented by its implementation in the
> kernel. Ideally it then receives an event back with the current log file's
> contents, which it then can save to disk.
> 
> There are unit tests of both the Gecko and Gaia sides of this equation but
> no integration tests yet.

Okay so far it does not work for me:
 - build fails because your patch does not yet contains the tests but defines them in the ini file
 - shaking the device produces no log
Flags: needinfo?(jhobin)
Thank you both very much for the quick and detailed reviews!

The reason I avoided using property_list is that it takes a c function pointer. I do not think js-ctypes can handle function pointers, so I essentially wrote a js-ified version of the property_list function.

As far as I can tell from searching bionic's libc, the only ways of accessing system properties are through __system_property_get, __system_property_set, __system_property_find, __system_property_read, and __system_property_find_nth. libcutil's property_list and my property_get_all employ the same subset of these functions.

From looking at properties.c, it looks like the Linux and Win32 implementations don't even provide property_list. Linux initializes the property server and returns while Win32 just returns 0.
Flags: needinfo?(jhobin)
The tests are now properly included in the patch. Hopefully the explanation for the logs not saving is that you didn't manually enable the setting (it defaults to being disabled).
Attachment #8438788 - Attachment is obsolete: true
Attachment #8438788 - Flags: review?(lissyx+mozillians)
Attachment #8439365 - Flags: review?(lissyx+mozillians)
I have also updated the Gaia PR. However, I did not see the mentioned lint failure on Travis (https://travis-ci.org/mozilla-b2g/gaia/jobs/27359805) and could not reproduce it locally.
Attachment #8438037 - Flags: review?(timdream)
(In reply to jhobin from comment #15)
> Thank you both very much for the quick and detailed reviews!
> 
> The reason I avoided using property_list is that it takes a c function
> pointer. I do not think js-ctypes can handle function pointers, so I
> essentially wrote a js-ified version of the property_list function.

I would be in favor of digging on this, I'm not sure ctypes does not allows this.

> 
> As far as I can tell from searching bionic's libc, the only ways of
> accessing system properties are through __system_property_get,
> __system_property_set, __system_property_find, __system_property_read, and
> __system_property_find_nth. libcutil's property_list and my property_get_all
> employ the same subset of these functions.
(In reply to jhobin from comment #16)
> Created attachment 8439365 [details] [diff] [review]
> Gecko-side implementation: Now with 100% more tests!
> 
> The tests are now properly included in the patch. Hopefully the explanation
> for the logs not saving is that you didn't manually enable the setting (it
> defaults to being disabled).

Sadly no, I took care of enabling the setting and rebooting with the setting enabled. Nothing in logcat either.
Update to the property_get_all kerfuffle: /dev/__properties__ is a special file which can be pulled and later parsed, circumventing the libc and libcutils functions. This seems more reasonable from a code perspective.

As a bonus, I have already written the parser required to put the file into Ptolemy (the log viewer app I'm developing in conjunction with this).
Now instead of using property_get_all it reads /dev/__properties__ as described above. This patch also fixes the unit tests (oops).
Attachment #8439365 - Attachment is obsolete: true
Attachment #8439365 - Flags: review?(lissyx+mozillians)
Attachment #8439602 - Flags: review?(lissyx+mozillians)
Comment on attachment 8439602 [details] [diff] [review]
Gecko-side implementation: Certified 100% libc free!

# HG changeset patch
# Parent c482c28b35b625f0a93e62871c8d4b77cb31230b

diff -r c482c28b35b6 b2g/chrome/content/shell.js
--- a/b2g/chrome/content/shell.js	Thu Jun 12 15:52:13 2014 +0100
+++ b/b2g/chrome/content/shell.js	Thu Jun 12 17:03:46 2014 -0700
@@ -106,6 +106,12 @@
 #endif
   },
 
+  get LogCapture() {
+    delete this.LogCapture;
+    Cu.import("resource://gre/modules/devtools/LogCapture.jsm", this);
+    return this.LogCapture;
+  },
+
   onlineForCrashReport: function shell_onlineForCrashReport() {
     let wifiManager = navigator.mozWifiManager;
     let onWifi = (wifiManager &&
@@ -1002,6 +1008,39 @@
   });
 });
 
+// Listen for log requests sent by Gaia. This follows the screenshot model,
+// using a mozContentEvent with detail.type set to 'capture-logs'. The logs are
+// then returned using a mozChromeEvent with detail.type 'capture-logs-success'
+// and the logs attached to detail.logs as a mapping of log location to Blob
+window.addEventListener('ContentStart', function captureLogs_onContentStart() {
+  let content = shell.contentBrowser.contentWindow;
+  content.addEventListener('mozContentEvent', function captureLogs_onMozContentEvent(e) {
+    if (e.detail.type !== 'capture-logs') {
+      return;
+    }
+
+    let logs = {};
+
+    // set of files which have log-type information
+    let logLocations = ['/dev/log/main', '/dev/log/system', '/dev/log/radio',
+                        '/dev/log/events', '/proc/kmsg', '/proc/meminfo',
+                        '/proc/version', '/dev/__properties__'];
+
+    logLocations.forEach(loc => {
+      let logArray = shell.LogCapture.readLogFile(loc);
+      let logBlob = new Blob([logArray],
+                             {type: 'application/octet-binary'});
+      logs[loc] = logBlob;
+    });
+
+    // Send the event to the requester
+    shell.sendChromeEvent({
+      type: 'capture-logs-success',
+      logs: logs
+    });
+  });
+});
+
 (function contentCrashTracker() {
   Services.obs.addObserver(function(aSubject, aTopic, aData) {
       let props = aSubject.QueryInterface(Ci.nsIPropertyBag2);
diff -r c482c28b35b6 toolkit/devtools/LogCapture.jsm
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/toolkit/devtools/LogCapture.jsm	Thu Jun 12 17:03:46 2014 -0700
@@ -0,0 +1,87 @@
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+'use strict';
+
+this.EXPORTED_SYMBOLS = ['LogCapture'];
+
+/**
+ * readLogFile
+ * Read in /dev/log/{{log}} in nonblocking mode, which will return -1 if
+ * reading would block the thread.
+ *
+ * @param log {String} The log from which to read. Must be present in /dev/log
+ * @return {Uint8Array} Raw log data
+ */
+let readLogFile = function(logLocation) {
+  if(!this.ctypes) {
+    // load in everything on first use
+    Components.utils.import('resource://gre/modules/ctypes.jsm', this);
+
+    this.lib = this.ctypes.open(this.ctypes.libraryName('c'));
+
+    this.read = this.lib.declare('read',
+      this.ctypes.default_abi,
+      this.ctypes.int,       // bytes read (out)
+      this.ctypes.int,       // file descriptor (in)
+      this.ctypes.voidptr_t, // buffer to read into (in)
+      this.ctypes.size_t     // size_t size of buffer (in)
+    );
+
+    this.open = this.lib.declare('open',
+      this.ctypes.default_abi,
+      this.ctypes.int,      // file descriptor (returned)
+      this.ctypes.char.ptr, // path
+      this.ctypes.int       // flags
+    );
+
+    this.close = this.lib.declare('close',
+      this.ctypes.default_abi,
+      this.ctypes.int, // error code (returned)
+      this.ctypes.int  // file descriptor
+    );
+  }
+
+  const O_READONLY = 0;
+  const O_NONBLOCK = 1 << 11;
+
+  const BUF_SIZE = 1024;
+
+  let BufType = this.ctypes.ArrayType(this.ctypes.char);
+  let buf = new BufType(BUF_SIZE);
+  let logArray = [];
+
+  let logFd = this.open(logLocation, O_READONLY | O_NONBLOCK);
+
+  while(true) {
+    let count = this.read(logFd, buf, BUF_SIZE);
+
+    if(count <= 0) {
+      // log has return due to being nonblocking or running out of things
+      break;
+    }
+
+    for(let i = 0; i < count; i++) {
+      logArray.push(buf[i]);
+    }
+  }
+
+  let logTypedArray = new Uint8Array(logArray.length);
+  for(let i = 0; i < logArray.length; i++) {
+    logTypedArray[i] = logArray[i];
+  }
+
+  this.close(logFd);
+
+  return logTypedArray;
+};
+
+let cleanup = function() {
+  this.lib.close();
+  this.read = this.open = this.close = null;
+  this.lib = null;
+  this.ctypes = null;
+};
+
+this.LogCapture = { readLogFile: readLogFile, cleanup: cleanup };
diff -r c482c28b35b6 toolkit/devtools/tests/unit/test_logcapture.js
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/toolkit/devtools/tests/unit/test_logcapture.js	Thu Jun 12 17:03:46 2014 -0700
@@ -0,0 +1,29 @@
+/* Any copyright is dedicated to the Public Domain.
+   http://creativecommons.org/publicdomain/zero/1.0/ */
+
+const { notEqual, ok } = Cu.import('resource://testing-common/Assert.jsm');
+const { LogCapture } = Cu.import('resources://gre/modules/devtools/LogCapture.jsm');
+
+/**
+ * Test that LogCapture successfully reads from the /dev/log devices, returning
+ * a Uint8Array of some length, including zero. This tests a few standard
+ * log devices
+ */
+function run_test() {
+  function verifyLog(log) {
+    // log exists
+    notEqual(log, null);
+    // log has a length and it is non-negative (is probably array-like)
+    ok(log.length >= 0);
+  }
+
+  let mainLog = LogCapture.readLogFile('/dev/log/main');
+  verifyLog(mainLog);
+
+  let systemLog = LogCapture.readLogFile('/dev/log/system');
+  verifyLog(systemLog);
+
+  let meminfoLog = LogCapture.readLogFile('/proc/meminfo');
+  verifyLog(meminfoLog);
+}
+
diff -r c482c28b35b6 toolkit/devtools/tests/unit/xpcshell.ini
--- a/toolkit/devtools/tests/unit/xpcshell.ini	Thu Jun 12 15:52:13 2014 +0100
+++ b/toolkit/devtools/tests/unit/xpcshell.ini	Thu Jun 12 17:03:46 2014 -0700
@@ -8,4 +8,5 @@
 [test_defineLazyPrototypeGetter.js]
 [test_async-utils.js]
 [test_consoleID.js]
-[test_require_lazy.js]
\ No newline at end of file
+[test_require_lazy.js]
+[test_logcapture.js]
Comment on attachment 8438037 [details] [review]
Gaia-side implementation

Almost almost, my intention was to share a few tricks to you so your constructor function can be created without any side effect.

Also the lint error was not fixed.
Attachment #8438037 - Flags: review?(timdream)
Thanks Tim! I was being rather dense and had forgotten about how the handleEvent function works. I also finally figured out how to view the lint errors, so those are now fixed. The pull request has been updated with the changes.
Attachment #8438037 - Flags: review?(timdream)
Attachment #8439602 - Attachment is obsolete: true
Attachment #8439602 - Flags: review?(lissyx+mozillians)
Attachment #8440041 - Flags: review?(lissyx+mozillians)
Do you mind adding much more debug logs in both gecko and gaia? Hidden being a DEBUG flag if you want :).

That would help me debug if it does not work. I'll test this on my device later this evening and review it.

What's the status of /dev/__properties__ ? Is it something stable or subject to changes later?
Flags: needinfo?(jhobin)
In this version the capture-logs handler now documents everything that it does as dumps with the string 'Logshake'
Flags: needinfo?(jhobin)
This is a patch for Gaia that adds a ridiculous amount of log statements to logshake.js. It can be applied with `patch -p1 < ../../gaia-1019816.patch` in a clean gaia source directory.
Depends on: 1025265
Comment on attachment 8440041 [details] [diff] [review]
Gecko-side implementation: Introducing this season's styles!

Review of attachment 8440041 [details] [diff] [review]:
-----------------------------------------------------------------

Since LogCapture.jsm is more B2G-specific for now, I think it makes sense that this file lives in b2g/components/.
I had a look at the shell.js code, and from testing also on device, your code present some behavior:
 - it can be triggered when the device is turned off (screen off). This is bad, it means we will keep listening on the devicemotion event and eventually never be able to sleep and go to suspend mode. This will lead to battery drainage, and phone taking logs when I'm riding my bike everyday.
 - there's a slight latency (2 secs at least) between the moment I'm shaking on Flame and the moment logs are dumped. I'm wondering if it would not be because you capture logs and send everything back to Gaia, causing quite a lot of trafic. This makes me wondering of the behavior on lower-end devices.

Also, as we said on IRC, there is quite a lot of room for improvements. But I think we can already land a first version where the current questions are addressed, and leave to the future:
 - making a zip file
 - making sure all dumped stuff are text file only, and maybe have a more complete version for your analysis tool
 - configuring the directory
 - configuring internal or external sd for dumping
 - capturing much more logs (you need to ask people what they need)
 - adding notification click handler to send a share MozActivity
 - implement a webapp to upload logs to bugzilla :)

::: toolkit/devtools/LogCapture.jsm
@@ +16,5 @@
> + * @return {Uint8Array} Raw log data
> + */
> +let readLogFile = function(logLocation) {
> +  if (!this.ctypes) {
> +    // load in everything on first use

So it means everytime we will shake the device, this jsm component will be loaded again and again?
I'm not sure we want to proceed like this, but rather have it sitting, listening for the setting change and load the LogCapture when the setting is enabled.

@@ +44,5 @@
> +    );
> +  }
> +
> +  const O_READONLY = 0;
> +  const O_NONBLOCK = 1 << 11;

Can't we load those from ctypes too?

@@ +54,5 @@
> +  let logArray = [];
> +
> +  let logFd = this.open(logLocation, O_READONLY | O_NONBLOCK);
> +
> +  while (true) {

Can't we use epoll() ?

::: toolkit/devtools/tests/unit/test_logcapture.js
@@ +1,4 @@
> +/* Any copyright is dedicated to the Public Domain.
> +   http://creativecommons.org/publicdomain/zero/1.0/ */
> +
> +const { notEqual, ok } = Cu.import('resource://testing-common/Assert.jsm');

It is my understanding that since Gecko 32 at least, this is done by default, so you don't have to load Assert.jsm in your test.

@@ +2,5 @@
> +   http://creativecommons.org/publicdomain/zero/1.0/ */
> +
> +const { notEqual, ok } = Cu.import('resource://testing-common/Assert.jsm');
> +const { LogCapture } = Cu.import('resources://gre/modules/devtools/LogCapture.jsm');
> +

I don't think those tests will be okay like this: you are running tests against real files but those won't be available on all system on which xpcshell tests will run.
Instead, maybe you should keep this test but limit it in xpcshell.ini to run only on emulator and device.
You will also want more test coverage for the whole system. I see that gaia code is unit-tested, that's a good thing :).
Attachment #8440041 - Flags: review?(lissyx+mozillians) → feedback+
Comment on attachment 8438037 [details] [review]
Gaia-side implementation

https://travis-ci.org/mozilla-b2g/gaia/jobs/27516002#L4161

Looks good, but please fix your unit test before landing!
Attachment #8438037 - Flags: review?(timdream) → review+
(In reply to Alexandre LISSY :gerard-majax from comment #29)
> Comment on attachment 8440041 [details] [diff] [review]
> Gecko-side implementation: Introducing this season's styles!
> 
> Review of attachment 8440041 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Since LogCapture.jsm is more B2G-specific for now, I think it makes sense
> that this file lives in b2g/components/.
> I had a look at the shell.js code, and from testing also on device, your
> code present some behavior:
>  - it can be triggered when the device is turned off (screen off). This is
> bad, it means we will keep listening on the devicemotion event and
> eventually never be able to sleep and go to suspend mode. This will lead to
> battery drainage, and phone taking logs when I'm riding my bike everyday.
>  - there's a slight latency (2 secs at least) between the moment I'm shaking
> on Flame and the moment logs are dumped. I'm wondering if it would not be
> because you capture logs and send everything back to Gaia, causing quite a
> lot of trafic. This makes me wondering of the behavior on lower-end devices.
> 
> Also, as we said on IRC, there is quite a lot of room for improvements. But
> I think we can already land a first version where the current questions are
> addressed, and leave to the future:
>  - making a zip file
>  - making sure all dumped stuff are text file only, and maybe have a more
> complete version for your analysis tool
>  - configuring the directory
>  - configuring internal or external sd for dumping
>  - capturing much more logs (you need to ask people what they need)
>  - adding notification click handler to send a share MozActivity
>  - implement a webapp to upload logs to bugzilla :)
> 
> ::: toolkit/devtools/LogCapture.jsm
> @@ +16,5 @@
> > + * @return {Uint8Array} Raw log data
> > + */
> > +let readLogFile = function(logLocation) {
> > +  if (!this.ctypes) {
> > +    // load in everything on first use
> 
> So it means everytime we will shake the device, this jsm component will be
> loaded again and again?
> I'm not sure we want to proceed like this, but rather have it sitting,
> listening for the setting change and load the LogCapture when the setting is
> enabled.
> 

The logshake module (apps/system/js/devtools/logshake.js) is the only loaded component at the start of execution. Upon receiving a settings event which enables it, logshake attaches a listener to motion. Only when the device is shaken does it dispatch the capture-logs event, which lazily loads LogCapture and LogParser (see shell.js line 109-119 for this). When used, LogCapture will load ctypes.jsm if it is not already available.

I may have messed up the implementation of this, but the intent is to have everything loaded on an as-needed basis.

> @@ +44,5 @@
> > +    );
> > +  }
> > +
> > +  const O_READONLY = 0;
> > +  const O_NONBLOCK = 1 << 11;
> 
> Can't we load those from ctypes too?
> 

From what I see in other code, there is no way to load #define directives using ctypes.

> @@ +54,5 @@
> > +  let logArray = [];
> > +
> > +  let logFd = this.open(logLocation, O_READONLY | O_NONBLOCK);
> > +
> > +  while (true) {
> 
> Can't we use epoll() ?
> 

I believe in this situation that using epoll() would require many more lines of code and potential logic errors than just using O_NONBLOCK. The use of O_NONBLOCK here is not to simulated event-ed IO, but to detect when the /dev/log special device is out of log entries.
Attached patch Gecko-side implementation (obsolete) — Splinter Review
I have also updated the pull request's code. I still need to add integration tests, but I would like to discuss the proper way to do that with a more experienced developer before I do so.
Attachment #8440041 - Attachment is obsolete: true
Attachment #8440072 - Attachment is obsolete: true
Attachment #8440078 - Attachment is obsolete: true
Attachment #8441064 - Flags: review?(lissyx+mozillians)
Comment on attachment 8441064 [details] [diff] [review]
Gecko-side implementation

Review of attachment 8441064 [details] [diff] [review]:
-----------------------------------------------------------------

I have not yet had a look at LogParser, will do later. We're on good track, but the SystemAppProxy is really needed.

::: b2g/chrome/content/shell.js
@@ +1014,3 @@
>    });
>  });
>  

The code added to shell.js should be under MOZ_WIDGET_GONK: it's not useful on B2G Desktop.

@@ +1019,5 @@
> +// then returned using a mozChromeEvent with detail.type 'capture-logs-success'
> +// and the logs attached to detail.logs as a mapping of log location to Blob
> +window.addEventListener('ContentStart', function captureLogs_onContentStart() {
> +  let content = shell.contentBrowser.contentWindow;
> +  content.addEventListener('mozContentEvent', function captureLogs_onMozContentEvent(e) {

Since this is communicating with the system app, you should use SystemAppProxy.

@@ +1040,5 @@
> +      if (loc.startsWith('/dev/log/')) {
> +        logArray = shell.LogParser.prettyPrintLogArrayBuffer(logArray.buffer);
> +      } else if (loc === '/dev/__properties__') {
> +        logArray = shell.LogParser.prettyPrintPropertiesArrayBuffer(logArray.buffer);
> +      }

This whole logic would make more sense being a property of the file themselves.
Maybe we should instead construct an object that makes the link between:
 - files
 - parsers

::: b2g/components/test/unit/xpcshell.ini
@@ +12,5 @@
>  tail =
>  
> +[test_logcapture.js]
> +# only run on b2g builds due to requiring b2g-specific log files to exist
> +skip-if = toolkit != "gonk"

Maybe you can make the test run on all platform by making it more generic?
Dumping the content of a device files and re-using in the tests :)

Specifically, only the part that does the reading from /dev/log is really gonk-specific, most of the code can be generic.

::: toolkit/devtools/tests/unit/xpcshell.ini
@@ +8,4 @@
>  [test_defineLazyPrototypeGetter.js]
>  [test_async-utils.js]
>  [test_consoleID.js]
> +[test_require_lazy.js]

Nothing changed there :)
Attachment #8441064 - Flags: review?(lissyx+mozillians) → feedback+
Comment on attachment 8441064 [details] [diff] [review]
Gecko-side implementation

Review of attachment 8441064 [details] [diff] [review]:
-----------------------------------------------------------------

::: b2g/components/LogParser.jsm
@@ +1,4 @@
> +/* jshint esnext: true */
> +/* global DataView, Uint8Array */
> +
> +'use strict';

You should be using double quotes.

@@ +3,5 @@
> +
> +'use strict';
> +
> +this.EXPORTED_SYMBOLS = ['LogParser'];
> +

I'd be happy that you provide some doc on the file format to avoid others to have to dig elsewhere :)

@@ +157,5 @@
> +  const PROP_VALUE_MAX = 92;
> +
> +  while (propIndex < propCount) {
> +    // retrieve offset from file start
> +    let infoOffset = data.getUint32(tocOffset, true) & 0xffffff;

Why the mask?
Whiteboard: [systemsfe]
Comment on attachment 8441064 [details] [diff] [review]
Gecko-side implementation

Review of attachment 8441064 [details] [diff] [review]:
-----------------------------------------------------------------

::: b2g/components/LogCapture.jsm
@@ +41,5 @@
> +    this.close = this.lib.declare('close',
> +      this.ctypes.default_abi,
> +      this.ctypes.int, // error code (returned)
> +      this.ctypes.int  // file descriptor
> +    );

Actually, why do we need to declare all of this instead of making use of OS.File?
(In reply to Alexandre LISSY :gerard-majax from comment #35)
> Comment on attachment 8441064 [details] [diff] [review]
> Gecko-side implementation
> 
> Review of attachment 8441064 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: b2g/components/LogCapture.jsm
> @@ +41,5 @@
> > +    this.close = this.lib.declare('close',
> > +      this.ctypes.default_abi,
> > +      this.ctypes.int, // error code (returned)
> > +      this.ctypes.int  // file descriptor
> > +    );
> 
> Actually, why do we need to declare all of this instead of making use of
> OS.File?

I just spent most of today refactoring to try to use OS.File. It worked for /dev/__properties__, but for every other log file it failed due to the underlying file not supporting a way of retrieving the file's size (like stat() or seek(SEEK_END)). The tricky thing with these special files is that they pretty much only support read() and--in the case of /dev/log/*-- will block read() when there is no more data available instead of returning 0.

I could modify OS.File to support unsized blind reads and to detect EAGAIN, but doing so seems far more clunky than using ctypes here.
Attached patch Gecko-side implementation (obsolete) — Splinter Review
Adds nearly every discussed change. The Gaia PR has also been slightly updated.
Attachment #8441064 - Attachment is obsolete: true
Attachment #8442562 - Flags: review?(lissyx+mozillians)
I'm very sorry for the delay, I got stuck on other bugs and have had no time to have a look and re-test your code :(
Comment on attachment 8442562 [details] [diff] [review]
Gecko-side implementation

Review of attachment 8442562 [details] [diff] [review]:
-----------------------------------------------------------------

It seems to be pretty good now. I'll do another round of on-device testing asap.

::: b2g/components/test/unit/test_logparser.js
@@ +28,5 @@
> +
> +  // Test arbitrary property entries for correctness
> +  equal(properties['ro.boot.console'], 'ttyHSL0');
> +  equal(properties['net.tcp.buffersize.lte'],
> +        '524288,1048576,2097152,262144,524288,1048576');

Any reason for using those properties? Specifically, the buffersize.lte may be risky (is LTE present everywhere?)
(In reply to Alexandre LISSY :gerard-majax from comment #39)
> Comment on attachment 8442562 [details] [diff] [review]
> Gecko-side implementation
> 
> Review of attachment 8442562 [details] [diff] [review]:
> -----------------------------------------------------------------
> ::: b2g/components/test/unit/test_logparser.js
> @@ +28,5 @@
> > +
> > +  // Test arbitrary property entries for correctness
> > +  equal(properties['ro.boot.console'], 'ttyHSL0');
> > +  equal(properties['net.tcp.buffersize.lte'],
> > +        '524288,1048576,2097152,262144,524288,1048576');
> 
> Any reason for using those properties? Specifically, the buffersize.lte may
> be risky (is LTE present everywhere?)

Those properties are being pulled from the sample file (b2g/components/test/unit/data/test_properties) and not from the device itself. They should only change if the parser has failed in some way.
Comment on attachment 8442562 [details] [diff] [review]
Gecko-side implementation

Review of attachment 8442562 [details] [diff] [review]:
-----------------------------------------------------------------

I didn't look in detail, but I have concerns over the split between gecko and gaia done here. What is the rationale for not doing everything in gecko?

::: b2g/chrome/content/shell.js
@@ +1006,5 @@
>  
> +#ifdef MOZ_WIDGET_GONK
> +// Listen for log requests sent by Gaia. This follows the screenshot model,
> +// using a mozContentEvent with detail.type set to 'capture-logs'. The logs are
> +// then returned using a mozChromeEvent with detail.type 'capture-logs-success'

don't reuse "mozChromeEvent". Use your own event name instead. Also, are you returning all the log content to gaia?
James, as far as I understand you haven't explained yet why you want to pass so much data from Gecko to Gaia just to perform saving. This was mentionned in comment 29, and Fabrice made a good point raising this again in comment 41. Is there any good reason for this ?

You also need to address the mozChromeEvent raised by Fabrice.
Flags: needinfo?(jhobin)
The current patches applies but build fails:

Traceback (most recent call last):
  File "/usr/lib/python2.7/runpy.py", line 162, in _run_module_as_main
    "__main__", fname, loader, pkg_name)
  File "/usr/lib/python2.7/runpy.py", line 72, in _run_code
    exec code in run_globals
  File "/home/alex/codaz/Mozilla/b2g/devices/Flame/B2G/gecko/python/mozbuild/mozbuild/action/process_install_manifest.py", line 60, in <module>
    main(sys.argv[1:])
  File "/home/alex/codaz/Mozilla/b2g/devices/Flame/B2G/gecko/python/mozbuild/mozbuild/action/process_install_manifest.py", line 51, in main
    remove_empty_directories=not args.no_remove_empty_directories)
  File "/home/alex/codaz/Mozilla/b2g/devices/Flame/B2G/gecko/python/mozbuild/mozbuild/action/process_install_manifest.py", line 30, in process_manifest
    remove_empty_directories=remove_empty_directories)
  File "/home/alex/codaz/Mozilla/b2g/devices/Flame/B2G/gecko/python/mozbuild/mozpack/copier.py", line 333, in copy
    if f.copy(destfile, skip_if_older):
  File "/home/alex/codaz/Mozilla/b2g/devices/Flame/B2G/gecko/python/mozbuild/mozpack/files.py", line 260, in copy
    raise ErrorMessage('Symlink target path does not exist: %s' % self.path)
mozpack.errors.ErrorMessage: Symlink target path does not exist: /home/alex/codaz/Mozilla/b2g/devices/Flame/B2G/gecko/b2g/components/test/unit/data/test_logger_file
make[4]: *** [install-tests] Erreur 1
make[3]: *** [default] Erreur 2
make[2]: *** [realbuild] Erreur 2
make[1]: *** [build] Erreur 2
make: *** [out/target/product/flame/obj/DATA/gecko_intermediates/gecko] Erreur 2
Comment on attachment 8442562 [details] [diff] [review]
Gecko-side implementation

Review of attachment 8442562 [details] [diff] [review]:
-----------------------------------------------------------------

After testing again, now that we log a lot more files, it's getting realy slow, especially on Flame.

It may takes several seconds to just get feedback that the log were registered. Could you please give a try to do as much as possible on Gecko side ?
And also address the previous issues, of course :)
Attachment #8442562 - Flags: review?(lissyx+mozillians)
I'm in the process of refactoring to divide gecko and gaia more performantly. However, in testing I've found that the actual cause of the slowdown is traversing the FFI layer thousands of times while reading /dev/log/* due to the devices' unique property of only reading one entry at a time. The easiest way to make this feel faster is probably vibrating at the beginning of the gesture in addition to when capturing the logs succeeds.

The current division between Gecko and Gaia is designed to allow a theoretical log viewer application to operate on-device without creating unnecessary temporary files. It also has the side effect of permitting easy transformation of log capture results to email attachments.

The test failure is due to my overlooking the including of the data files for the test files in my patch and will be corrected in the next version.
Flags: needinfo?(jhobin)
Attached patch Gecko-side implementation (obsolete) — Splinter Review
This shifts around the layout of components between Gecko and Gaia, reworking some of the tests and drastically reducing the amount of data passed through events. The test of LogShake on the Gecko side is somewhat iffy, but I'm not sure how to improve it without creating a test that will take multiple seconds to run.
Attachment #8442562 - Attachment is obsolete: true
Attachment #8451811 - Flags: review?(lissyx+mozillians)
moz.build part has changed and does not apply :(
(In reply to jhobin from comment #46)
> Created attachment 8451811 [details] [diff] [review]
> Gecko-side implementation
> 
> This shifts around the layout of components between Gecko and Gaia,
> reworking some of the tests and drastically reducing the amount of data
> passed through events. The test of LogShake on the Gecko side is somewhat
> iffy, but I'm not sure how to improve it without creating a test that will
> take multiple seconds to run.

James, there's something broken: I can get the log dumped one first time properly, but any further subsequent attempt does not do anything. Meanwhile, I noticed a very nice improvement in the delay :)
Comment on attachment 8451811 [details] [diff] [review]
Gecko-side implementation

Review of attachment 8451811 [details] [diff] [review]:
-----------------------------------------------------------------

Having a look at the produced logs, I noticed some extra line returns being present in my /dev/log/system, /dev/log/radio and /dev/log/main.
I'm waiting for a version where I can shake several times :).

::: b2g/components/LogShake.jsm
@@ +30,5 @@
> +  }
> +  return logName + '.log';
> +}
> +
> +function getSdcardPrefix() {

Can we just make sure of the behavior on a device with no sdcard at all (Flame has an internal one) ? At least make sure we do not break and maybe send a logcat error.

@@ +86,5 @@
> +
> +  let sdcardPrefix = getSdcardPrefix();
> +  let dirName = getLogDirectory();
> +  debug('making a directory all the way from '+sdcardPrefix+' to '+(sdcardPrefix + '/' + dirName));
> +  return OS.File.makeDir(sdcardPrefix + '/' + dirName, {from: sdcardPrefix})

We have OS.Path.join(), that would be more reliable I think.

@@ +98,5 @@
> +      let logArray = logArrays[logLocation];
> +      // The filename represents the relative path within the SD card, not the
> +      // absolute path because Gaia will refer to it using the DeviceStorage
> +      // API
> +      let filename = dirName + getLogFilename(logLocation);

Same, OS.Path.join() and its little brothers :)

::: b2g/components/moz.build
@@ +49,5 @@
>      'ContentRequestHelper.jsm',
>      'ErrorPage.jsm',
> +    'LogCapture.jsm',
> +    'LogParser.jsm',
> +    'LogShake.jsm',

This has bitrotten, but nothing grave :)
Attachment #8451811 - Flags: review?(lissyx+mozillians)
Attached patch bug1019816.patch (obsolete) — Splinter Review
I ironed out the bugs in the implementation (at least, I believe I ironed out the bugs). This updates both the Gaia and Gecko sides.
Attachment #8451811 - Attachment is obsolete: true
Attachment #8454704 - Flags: review?(lissyx+mozillians)
Comment on attachment 8454704 [details] [diff] [review]
bug1019816.patch

Review of attachment 8454704 [details] [diff] [review]:
-----------------------------------------------------------------

Sorry for those late big changes, but re-thinking about this I think we could limit the changes to shell.js a lot more and make the code more self-contained.

::: b2g/chrome/content/shell.js
@@ +103,5 @@
>  #endif
>    },
>  
> +#ifdef MOZ_WIDGET_GONK
> +  get LogShake() {

I'm not sure we really need to do it this way. We could just always import this JSM, and have it handle all the events logic instead.

@@ +1000,5 @@
> +// save log files to an arbitrary directory which it will then return on a
> +// 'capture-logs-success' event with detail.logFilenames representing each log
> +// file's filename in the directory
> +window.addEventListener('ContentStart', function captureLogs_onContentStart() {
> +  let content = shell.contentBrowser.contentWindow;

You are still not using SystemAppProxy.

@@ +1001,5 @@
> +// 'capture-logs-success' event with detail.logFilenames representing each log
> +// file's filename in the directory
> +window.addEventListener('ContentStart', function captureLogs_onContentStart() {
> +  let content = shell.contentBrowser.contentWindow;
> +  content.addEventListener('capture-logs', function captureLogs_onCaptureLogsEvent(e) {

SystemAppProxy.addEventListener('capture-logs-start')

::: b2g/components/LogShake.jsm
@@ +4,5 @@
> +/* jshint moz: true */
> +/* global Blob, Components, dump, LogCapture, LogParser, OS, Promise, Uint8Array, volumeService, XPCOMUtils */
> +'use strict';
> +
> +Components.utils.import('resource://gre/modules/LogCapture.jsm');

const Cu = Components.utils;

Cu.import(...);

@@ +16,5 @@
> +XPCOMUtils.defineLazyServiceGetter(this, "volumeService",
> +                                   "@mozilla.org/telephony/volume-service;1",
> +                                   "nsIVolumeService");
> +
> +this.EXPORTED_SYMBOLS = ['LogShake'];

We may be able to avoid this. Let's create a LogShake object within this file, with all the functions being its members.
Make sure there's an init() method, this one will take care of registering events:
 - settings listener to enable the shaking detection when the setting value changes
 - screen state to enable the shaking detection only when the screen is powered on
 - xpcom-shutdown to make sure we do not leak listeners and resources
And of course the SystemAppProxy events listener.

@@ +100,5 @@
> +      let logArray = logArrays[logLocation];
> +      // The filename represents the relative path within the SD card, not the
> +      // absolute path because Gaia will refer to it using the DeviceStorage
> +      // API
> +      let filename = dirName + getLogFilename(logLocation);

There may be a nicer way to build this path :)
Attachment #8454704 - Flags: review?(lissyx+mozillians)
James, sorry for asking that much changes. Meanwhile, I could reproduce the issue and gather more logs:

I/GeckoDump(  298): LogShake: requesting capture!
I/GeckoDump(  298): LogShake: starting captureLogs listener
I/GeckoDump(  298): Logshake: Done?!?!?!?!?!?
I/GeckoDump(  298): LogShake: handling capture-logs-success
I/GeckoDump(  298): LogShake: requesting capture!
I/GeckoDump(  298): LogShake: starting captureLogs listener
I/Gecko   (  298): *************************
I/Gecko   (  298): A coding exception was thrown and uncaught in a Task.
I/Gecko   (  298): 
I/Gecko   (  298): Full message: TypeError: C pointer missing bytes indication.
I/Gecko   (  298): Full stack: normalizeToPointer@resource://gre/modules/osfile/osfile_shared_allthreads.jsm:1215:13
I/Gecko   (  298): write@resource://gre/modules/osfile/osfile_shared_front.jsm:126:7
I/Gecko   (  298): writeAtomic@resource://gre/modules/osfile/osfile_shared_front.jsm:453:22
I/Gecko   (  298): writeAtomic@resource://gre/modules/osfile/osfile_async_worker.js:266:1
I/Gecko   (  298): worker.dispatch@resource://gre/modules/osfile/osfile_async_worker.js:31:26
I/Gecko   (  298): require._tmpModules[":resource://gre/modules/workers/PromiseWorker.js"]/AbstractWorker.prototype.handleMessage@resource://gre/modules/workers/PromiseWorker.js:122:16
I/Gecko   (  298): @resource://gre/modules/osfile/osfile_async_worker.js:46:43
I/Gecko   (  298): 
I/Gecko   (  298): *************************
I/Gecko   (  298): *************************
I/Gecko   (  298): A coding exception was thrown and uncaught in a Task.
I/Gecko   (  298): 
I/Gecko   (  298): Full message: TypeError: C pointer missing bytes indication.
I/Gecko   (  298): Full stack: normalizeToPointer@resource://gre/modules/osfile/osfile_shared_allthreads.jsm:1215:13
I/Gecko   (  298): write@resource://gre/modules/osfile/osfile_shared_front.jsm:126:7
I/Gecko   (  298): writeAtomic@resource://gre/modules/osfile/osfile_shared_front.jsm:453:22
I/Gecko   (  298): writeAtomic@resource://gre/modules/osfile/osfile_async_worker.js:266:1
I/Gecko   (  298): worker.dispatch@resource://gre/modules/osfile/osfile_async_worker.js:31:26
I/Gecko   (  298): require._tmpModules[":resource://gre/modules/workers/PromiseWorker.js"]/AbstractWorker.prototype.handleMessage@resource://gre/modules/workers/PromiseWorker.js:122:16
I/Gecko   (  298): @resource://gre/modules/osfile/osfile_async_worker.js:46:43
I/Gecko   (  298): 
I/Gecko   (  298): *************************
I/GeckoDump(  298): Logshake error: TypeError: C pointer missing bytes indication.
I/GeckoDump(  298): LogShake: screen is false
I/GeckoDump(  298): LogShake: stopping motion listener
Flags: needinfo?(jhobin)
David, can you have a look at comment 52 ? I'm wondering if it's a bug in James' code or that he is exposing something that may be of interest to you :)
Flags: needinfo?(dteller)
Do we gather enough information to reproduce the output of adb logcat -v threadtime ?

I find having the timestamps and the thread id are extremely useful for me.
(In reply to Dave Hylands [:dhylands] from comment #54)
> Do we gather enough information to reproduce the output of adb logcat -v
> threadtime ?
> 
> I find having the timestamps and the thread id are extremely useful for me.

07-12 18:57:30.570   298   298 I GeckoDump: LogShake: requesting capture!
07-12 18:57:30.570   298   298 I GeckoDump: LogShake: starting captureLogs listener
07-12 18:57:32.530   298   298 I GeckoDump: Logshake: Done?!?!?!?!?!?
07-12 18:57:32.530   298   298 I GeckoDump: LogShake: handling capture-logs-success
07-12 18:57:34.490   298   298 I GeckoDump: LogShake: requesting capture!
07-12 18:57:34.490   298   298 I GeckoDump: LogShake: starting captureLogs listener
07-12 18:57:36.000   298   298 I Gecko   : *************************
07-12 18:57:36.000   298   298 I Gecko   : A coding exception was thrown and uncaught in a Task.
07-12 18:57:36.000   298   298 I Gecko   : 
07-12 18:57:36.000   298   298 I Gecko   : Full message: TypeError: C pointer missing bytes indication.
07-12 18:57:36.000   298   298 I Gecko   : Full stack: normalizeToPointer@resource://gre/modules/osfile/osfile_shared_allthreads.jsm:1215:13
07-12 18:57:36.000   298   298 I Gecko   : write@resource://gre/modules/osfile/osfile_shared_front.jsm:126:7
07-12 18:57:36.000   298   298 I Gecko   : writeAtomic@resource://gre/modules/osfile/osfile_shared_front.jsm:453:22
07-12 18:57:36.000   298   298 I Gecko   : writeAtomic@resource://gre/modules/osfile/osfile_async_worker.js:266:1
07-12 18:57:36.000   298   298 I Gecko   : worker.dispatch@resource://gre/modules/osfile/osfile_async_worker.js:31:26
07-12 18:57:36.000   298   298 I Gecko   : require._tmpModules[":resource://gre/modules/workers/PromiseWorker.js"]/AbstractWorker.prototype.handleMessage@resource://gre/modules/workers/PromiseWorker.js:122:16
07-12 18:57:36.000   298   298 I Gecko   : @resource://gre/modules/osfile/osfile_async_worker.js:46:43
07-12 18:57:36.000   298   298 I Gecko   : 
07-12 18:57:36.000   298   298 I Gecko   : *************************
07-12 18:57:36.000   298   298 I Gecko   : *************************
07-12 18:57:36.000   298   298 I Gecko   : A coding exception was thrown and uncaught in a Task.
07-12 18:57:36.000   298   298 I Gecko   : 
07-12 18:57:36.000   298   298 I Gecko   : Full message: TypeError: C pointer missing bytes indication.
07-12 18:57:36.000   298   298 I Gecko   : Full stack: normalizeToPointer@resource://gre/modules/osfile/osfile_shared_allthreads.jsm:1215:13
07-12 18:57:36.000   298   298 I Gecko   : write@resource://gre/modules/osfile/osfile_shared_front.jsm:126:7
07-12 18:57:36.000   298   298 I Gecko   : writeAtomic@resource://gre/modules/osfile/osfile_shared_front.jsm:453:22
07-12 18:57:36.000   298   298 I Gecko   : writeAtomic@resource://gre/modules/osfile/osfile_async_worker.js:266:1
07-12 18:57:36.000   298   298 I Gecko   : worker.dispatch@resource://gre/modules/osfile/osfile_async_worker.js:31:26
07-12 18:57:36.000   298   298 I Gecko   : require._tmpModules[":resource://gre/modules/workers/PromiseWorker.js"]/AbstractWorker.prototype.handleMessage@resource://gre/modules/workers/PromiseWorker.js:122:16
07-12 18:57:36.000   298   298 I Gecko   : @resource://gre/modules/osfile/osfile_async_worker.js:46:43
07-12 18:57:36.000   298   298 I Gecko   : 
07-12 18:57:36.000   298   298 I Gecko   : *************************
07-12 18:57:36.000   298   298 I GeckoDump: Logshake error: TypeError: C pointer missing bytes indication.
07-12 18:57:38.590   298   298 I GeckoDump: LogShake: screen is false
07-12 18:57:38.590   298   298 I GeckoDump: LogShake: stopping motion listener
07-12 18:57:38.590   298   298 E Sensors : change G sensor state "1 -> 0"
I seem to remember that this error message shows up if we pass an empty array/string to write (bug 1023685). Could this be the case?
Flags: needinfo?(dteller)
James, after thinking again and talking with fabrice, we don't see any reason to keep anything in Gaia but the Notification handling. Everything can be done on Gecko side, which will notify Gaia when the dump has been performed. Hence, gaia system changes will only send a Notification and add handlers on it.
(In reply to Dave Hylands [:dhylands] from comment #54)
> Do we gather enough information to reproduce the output of adb logcat -v
> threadtime ?
> 
> I find having the timestamps and the thread id are extremely useful for me.

Yes, the default output is in threadtime format.

(In reply to Alexandre LISSY :gerard-majax from comment #57)
> James, after thinking again and talking with fabrice, we don't see any
> reason to keep anything in Gaia but the Notification handling. Everything
> can be done on Gecko side, which will notify Gaia when the dump has been
> performed. Hence, gaia system changes will only send a Notification and add
> handlers on it.

While I believe that putting as many things behind-the-scenes in Gecko is a good idea, this will require a bit of research on how best to access the window and navigator objects (for event listening and settings access).

I do like the current split for how it interacts with the lazy-loading of LogShake.jsm. In theory it has less memory usage than the all-in-Gecko design, although it's definitely possible to fix that with clever optimization.

(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo") from comment #56)
> I seem to remember that this error message shows up if we pass an empty
> array/string to write (bug 1023685). Could this be the case?

If this is the case, the easiest way to fix it would be by ignoring empty log files. However, I find that solution potentially problematic as the absence of contents in a log file has the potential to be meaningful.
Flags: needinfo?(jhobin)
Well, we could bump up the priority of bug 1023685. I kept it as a good first bug, but I can trivially fix it myself.
(In reply to jhobin from comment #58)

> While I believe that putting as many things behind-the-scenes in Gecko is a
> good idea, this will require a bit of research on how best to access the
> window and navigator objects (for event listening and settings access).

In shell.js you are in a window so you can access what you need.

> I do like the current split for how it interacts with the lazy-loading of
> LogShake.jsm. In theory it has less memory usage than the all-in-Gecko
> design, although it's definitely possible to fix that with clever
> optimization.

Not sure what you mean there... there should be no difference in memory usage with an all-in-gecko version.
(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo") from comment #59)
> Well, we could bump up the priority of bug 1023685. I kept it as a good
> first bug, but I can trivially fix it myself.

I like it more as a good first bug. I'm willing to find a workaround.

(In reply to Fabrice Desré [:fabrice] from comment #60)
> (In reply to jhobin from comment #58)
> 
> > While I believe that putting as many things behind-the-scenes in Gecko is a
> > good idea, this will require a bit of research on how best to access the
> > window and navigator objects (for event listening and settings access).
> 
> In shell.js you are in a window so you can access what you need.
> 

Yes, but LogShake is loaded from a JSM, which I believe has no access to window or navigator objects.

> > I do like the current split for how it interacts with the lazy-loading of
> > LogShake.jsm. In theory it has less memory usage than the all-in-Gecko
> > design, although it's definitely possible to fix that with clever
> > optimization.
> 
> Not sure what you mean there... there should be no difference in memory
> usage with an all-in-gecko version.

A naive refactor would not use more memory overall, but it would use more memory when LogShake is disabled. However, this should be easy to fix.
> (In reply to Fabrice Desré [:fabrice] from comment #60)
> > (In reply to jhobin from comment #58)
> > 
> > > While I believe that putting as many things behind-the-scenes in Gecko is a
> > > good idea, this will require a bit of research on how best to access the
> > > window and navigator objects (for event listening and settings access).
> > 
> > In shell.js you are in a window so you can access what you need.
> > 
> 
> Yes, but LogShake is loaded from a JSM, which I believe has no access to
> window or navigator objects.
> 

I was wrong! SystemAppProxy is wonderful and amazing.
James, any news?
Flags: needinfo?(jhobin)
This patch moves everything but the notification production to Gecko-land. It should solve every outstanding issue and makes admirable use of SystemAppProxy. 

The unit tests do take longer than I believe they should, but I am not sure what is causing that.
Attachment #8454704 - Attachment is obsolete: true
Attachment #8461259 - Flags: review?(lissyx+mozillians)
Flags: needinfo?(jhobin)
Comment on attachment 8461259 [details] [diff] [review]
Gecko-side implementation: Gecko Harder

Review of attachment 8461259 [details] [diff] [review]:
-----------------------------------------------------------------

This is looking much better. There are still a couple of things that I think you should address, but hopefully this will be the last round.
Testing it on my device (Flame, 1GB), it works quite well, and it's reactive enough :)

::: b2g/components/LogShake.jsm
@@ +30,5 @@
> +Cu.import('resource://gre/modules/osfile/ospath.jsm');
> +Cu.import('resource://gre/modules/Promise.jsm');
> +Cu.import('resource://gre/modules/Services.jsm');
> +Cu.import('resource://gre/modules/SystemAppProxy.jsm');
> +Cu.import('resource://gre/modules/XPCOMUtils.jsm');

Please use as much as possible of XPCOMUtils.defineLazyModuleGetter ?

@@ +120,5 @@
> +  /**
> +   * Handle an arbitrary event, passing it along to the proper function
> +   */
> +  handleEvent: function(event) {
> +    if (event.type === DEVICE_MOTION_EVENT) {

I would prefer using switch(event.type)

@@ +184,5 @@
> +     }
> +  },
> +
> +  startDeviceMotionListener: function() {
> +    SystemAppProxy.addEventListener(DEVICE_MOTION_EVENT, this, false);

I don't think this makes sense, devicemotion is not an event between Gecko and system app

::: b2g/components/test/unit/test_logshake.js
@@ +57,5 @@
> +SettingsHandler.prototype.QueryInterface = XPCOMUtils.generateQI([Ci.nsISettingsServiceCallback]);
> +
> +// Force a test function to run with or without LogShake enabled.
> +// This strangeness hopefully avoids the race between Services.obs and the
> +// callback which breaks the naive approach.

Can you elaborate on this ?
Attachment #8461259 - Flags: review?(lissyx+mozillians) → feedback+
(In reply to Alexandre LISSY :gerard-majax from comment #65)
> Comment on attachment 8461259 [details] [diff] [review]
> Gecko-side implementation: Gecko Harder
> 
> Review of attachment 8461259 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> This is looking much better. There are still a couple of things that I think
> you should address, but hopefully this will be the last round.
> Testing it on my device (Flame, 1GB), it works quite well, and it's reactive
> enough :)
> 
> ::: b2g/components/LogShake.jsm
> @@ +30,5 @@
> > +Cu.import('resource://gre/modules/osfile/ospath.jsm');
> > +Cu.import('resource://gre/modules/Promise.jsm');
> > +Cu.import('resource://gre/modules/Services.jsm');
> > +Cu.import('resource://gre/modules/SystemAppProxy.jsm');
> > +Cu.import('resource://gre/modules/XPCOMUtils.jsm');
> 
> Please use as much as possible of XPCOMUtils.defineLazyModuleGetter ?
> 
I think I can lazy-get everything but OS.File/OS.Path because they use the same top-level symbol. Is this correct? (I could not find any instances of lazy-getting both of them in Gecko)

> @@ +184,5 @@
> > +     }
> > +  },
> > +
> > +  startDeviceMotionListener: function() {
> > +    SystemAppProxy.addEventListener(DEVICE_MOTION_EVENT, this, false);
> 
> I don't think this makes sense, devicemotion is not an event between Gecko
> and system app
> 
As far as I can tell, the devicemotion event is only associated with the DOM window, allowing SystemAppProxy to be used to pick it up. A cursory glance did not find any WebIDL or equivalent bindings for accessing device motion through other means.

> ::: b2g/components/test/unit/test_logshake.js
> @@ +57,5 @@
> > +SettingsHandler.prototype.QueryInterface = XPCOMUtils.generateQI([Ci.nsISettingsServiceCallback]);
> > +
> > +// Force a test function to run with or without LogShake enabled.
> > +// This strangeness hopefully avoids the race between Services.obs and the
> > +// callback which breaks the naive approach.
> 
> Can you elaborate on this ?

Services.obs adds a callback on settings changes, as does the test. However, the test's callback is called before the Services.obs callback due to the structuring of the dispatch function in SettingsService. Therefore, to properly ensure that the `devtools.logshake` setting is set and propagated, I call the `set` function twice. Because SettingsService guarantees the mutual exclusion of `set` operations on the same key, the test function ends up guaranteed to be operating in a context in which Services.obs has notified LogShake about the state of the `devtools.logshake` setting.
Alex, any feedback on whether using SystemAppProxy for devicemotion is permissible?
Flags: needinfo?(lissyx+mozillians)
(In reply to jhobin from comment #66)
> (In reply to Alexandre LISSY :gerard-majax from comment #65)
> > Comment on attachment 8461259 [details] [diff] [review]
> > Gecko-side implementation: Gecko Harder
> > 
> > Review of attachment 8461259 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > This is looking much better. There are still a couple of things that I think
> > you should address, but hopefully this will be the last round.
> > Testing it on my device (Flame, 1GB), it works quite well, and it's reactive
> > enough :)
> > 
> > ::: b2g/components/LogShake.jsm
> > @@ +30,5 @@
> > > +Cu.import('resource://gre/modules/osfile/ospath.jsm');
> > > +Cu.import('resource://gre/modules/Promise.jsm');
> > > +Cu.import('resource://gre/modules/Services.jsm');
> > > +Cu.import('resource://gre/modules/SystemAppProxy.jsm');
> > > +Cu.import('resource://gre/modules/XPCOMUtils.jsm');
> > 
> > Please use as much as possible of XPCOMUtils.defineLazyModuleGetter ?
> > 
> I think I can lazy-get everything but OS.File/OS.Path because they use the
> same top-level symbol. Is this correct? (I could not find any instances of
> lazy-getting both of them in Gecko)

You can always try :). And maybe we want to fix this, if it does not work.

> 
> > @@ +184,5 @@
> > > +     }
> > > +  },
> > > +
> > > +  startDeviceMotionListener: function() {
> > > +    SystemAppProxy.addEventListener(DEVICE_MOTION_EVENT, this, false);
> > 
> > I don't think this makes sense, devicemotion is not an event between Gecko
> > and system app
> > 
> As far as I can tell, the devicemotion event is only associated with the DOM
> window, allowing SystemAppProxy to be used to pick it up. A cursory glance
> did not find any WebIDL or equivalent bindings for accessing device motion
> through other means.

I'm not sure then. I still don't feel confident using SystemAppProxy for this. Maybe you can have a look at the use of chromeEventHandler in shell.js ?

> 
> > ::: b2g/components/test/unit/test_logshake.js
> > @@ +57,5 @@
> > > +SettingsHandler.prototype.QueryInterface = XPCOMUtils.generateQI([Ci.nsISettingsServiceCallback]);
> > > +
> > > +// Force a test function to run with or without LogShake enabled.
> > > +// This strangeness hopefully avoids the race between Services.obs and the
> > > +// callback which breaks the naive approach.
> > 
> > Can you elaborate on this ?
> 
> Services.obs adds a callback on settings changes, as does the test. However,
> the test's callback is called before the Services.obs callback due to the
> structuring of the dispatch function in SettingsService. Therefore, to
> properly ensure that the `devtools.logshake` setting is set and propagated,
> I call the `set` function twice. Because SettingsService guarantees the
> mutual exclusion of `set` operations on the same key, the test function ends
> up guaranteed to be operating in a context in which Services.obs has
> notified LogShake about the state of the `devtools.logshake` setting.

Okay. Can you get fabrice to cross check this ?
Flags: needinfo?(lissyx+mozillians)
As far as I can tell, SystemAppProxy (or equivalent, e.g. chromeEventHandler with a Services.wm call) use is required due to the noscripting of nsIDeviceSensor's listener adding functions paired with the tagging of the "devicemotion" event as window-only. I prefer SystemAppProxy because it is proven to work and handles window-availability race conditions.

Otherwise, this patch now lazy-gets everything, including OS.File and OS.Path.
Attachment #8461259 - Attachment is obsolete: true
Attachment #8467360 - Flags: review?(lissyx+mozillians)
Comment on attachment 8467360 [details] [diff] [review]
Gecko-side implementation: Gecko with a Vengeance

Review of attachment 8467360 [details] [diff] [review]:
-----------------------------------------------------------------

Mostly fine by me after testing on the device. I'm having a look at some formatting issues I've noticed when messages may contain multiple '\n'.

::: b2g/components/LogShake.jsm
@@ +18,5 @@
> +/* jshint -W040 */
> +/* global Services, settingsService, Components, dump, LogCapture, LogParser,
> +   OS, Promise, volumeService, XPCOMUtils, SystemAppProxy */
> +
> +'use strict';

Double quotes, everywhere.
Attachment #8467360 - Flags: review?(lissyx+mozillians) → review+
Comment on attachment 8467360 [details] [diff] [review]
Gecko-side implementation: Gecko with a Vengeance

Review of attachment 8467360 [details] [diff] [review]:
-----------------------------------------------------------------

Actually, sorry, I still see some not nice logcat output that make it not easy to read.
Attachment #8467360 - Flags: review+
Attached file expected-logcat.log
This is the logcat output I expect to see.
Flags: needinfo?(hobinjk)
Attached file dev-log-main.log
This is the current dump logcat. Please note the two discrepencies:
 - extra line return are present in your logcat output
 - some lines misses the starting parts, like the skia ones.

This may seems a small issue, but I fear this will produce logs that are hard to exploit.
(In reply to Alexandre LISSY :gerard-majax from comment #72)
> Created attachment 8467799 [details]
> expected-logcat.log
> 
> This is the logcat output I expect to see.

Thanks for pointing this out! I had forgotten to ensure this was properly fixed (most log entries are conformant, of course). I also found a potential for buffer overrun causing a JavaScript exception based on messages of length 4096-something which I have fixed.

I'm testing my modifications now, but there should be a patch in the next hour.
Flags: needinfo?(hobinjk)
Attachment #8467360 - Attachment is obsolete: true
Attachment #8468045 - Flags: review?(lissyx+mozillians)
Comment on attachment 8468045 [details] [diff] [review]
Gecko-side implementation: Live Free or Gecko

Review of attachment 8468045 [details] [diff] [review]:
-----------------------------------------------------------------

It has improved the output for some lines, but I still see bad things, where we have lines missing the date/time/process etc.:
 - skia lines dumps
 - Adreno-EGL dumps

I also saw some empty lines after some 'rmt_storage_client_thread' dump, but I would not block on this one since empty lines are less problematics.

Thanks for your efforts, we are nearly there :)
Attachment #8468045 - Flags: review?(lissyx+mozillians) → feedback+
Attached file bogus adreno-egl lines
Attached file bogus skia lines
(In reply to Alexandre LISSY :gerard-majax from comment #76)
> Comment on attachment 8468045 [details] [diff] [review]
> Gecko-side implementation: Live Free or Gecko
> 
> Review of attachment 8468045 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> It has improved the output for some lines, but I still see bad things, where
> we have lines missing the date/time/process etc.:
>  - skia lines dumps
>  - Adreno-EGL dumps
> 
> I also saw some empty lines after some 'rmt_storage_client_thread' dump, but
> I would not block on this one since empty lines are less problematics.
> 
> Thanks for your efforts, we are nearly there :)

Interesting! It turns out that Logcat reinterprets newlines in log messages as the start of a new log message. This is, of course, implemented by logprint.c in a block of code with the disclaimer, "/* the following code is tragically unreadable */"
Patch properly handling newlines. Hopefully this fixes everything, I am out of Die Hard movies to name the patches after :)
Attachment #8468045 - Attachment is obsolete: true
Attachment #8468648 - Flags: review?(lissyx+mozillians)
Comment on attachment 8468648 [details] [diff] [review]
Gecko-side implementation: A Good Day to Gecko

Review of attachment 8468648 [details] [diff] [review]:
-----------------------------------------------------------------

I cannot find anything else to criticize :)
Attachment #8468648 - Flags: review?(lissyx+mozillians) → review+
Whiteboard: [systemsfe] → [systemsfe] [checkin-needed]
Keywords: checkin-needed
Whiteboard: [systemsfe] [checkin-needed] → [systemsfe]
Is there a recent Try link handy for this? :)
Keywords: checkin-needed
I'm removing the feature 2.1 flag and adding to backlog.  That just means we're not targeting it for 2.1 officially (for the purposes of outbound communication).  That doesn't change whether or not it should land, though.
blocking-b2g: --- → backlog
feature-b2g: 2.1 → ---
Depends on: 1053669
(In reply to Gregor Wagner [:gwagner] from comment #87)
> try run:
> https://tbpl.mozilla.org/?tree=Try&rev=efb40867646c

This is not passing.

https://tbpl.mozilla.org/php/getParsedLog.php?id=45916081&tree=Try
Flags: needinfo?(jhobin)
(In reply to Alexandre LISSY :gerard-majax from comment #88)
> (In reply to Gregor Wagner [:gwagner] from comment #87)
> > try run:
> > https://tbpl.mozilla.org/?tree=Try&rev=efb40867646c
> 
> This is not passing.
> 
> https://tbpl.mozilla.org/php/getParsedLog.php?id=45916081&tree=Try

This appears to be a difference between the emulator and the physical Flame device.

I modified the test slightly to reflect that /dev/log/system is not guaranteed to exist.

A new try build is available at https://tbpl.mozilla.org/?tree=Try&rev=e74caeede310
Flags: needinfo?(jhobin)
(In reply to jhobin from comment #89)
> (In reply to Alexandre LISSY :gerard-majax from comment #88)
> > (In reply to Gregor Wagner [:gwagner] from comment #87)
> > > try run:
> > > https://tbpl.mozilla.org/?tree=Try&rev=efb40867646c
> > 
> > This is not passing.
> > 
> > https://tbpl.mozilla.org/php/getParsedLog.php?id=45916081&tree=Try
> 
> This appears to be a difference between the emulator and the physical Flame
> device.
> 
> I modified the test slightly to reflect that /dev/log/system is not
> guaranteed to exist.
> 
> A new try build is available at
> https://tbpl.mozilla.org/?tree=Try&rev=e74caeede310

Looks like it's better but now it crashed during your test :)

https://tbpl.mozilla.org/php/getParsedLog.php?id=45976430&tree=Try#error0
Flags: needinfo?(jhobin)
(In reply to Alexandre LISSY :gerard-majax from comment #90)
> (In reply to jhobin from comment #89)
> > (In reply to Alexandre LISSY :gerard-majax from comment #88)
> > > (In reply to Gregor Wagner [:gwagner] from comment #87)
> > > > try run:
> > > > https://tbpl.mozilla.org/?tree=Try&rev=efb40867646c
> > > 
> > > This is not passing.
> > > 
> > > https://tbpl.mozilla.org/php/getParsedLog.php?id=45916081&tree=Try
> > 
> > This appears to be a difference between the emulator and the physical Flame
> > device.
> > 
> > I modified the test slightly to reflect that /dev/log/system is not
> > guaranteed to exist.
> > 
> > A new try build is available at
> > https://tbpl.mozilla.org/?tree=Try&rev=e74caeede310
> 
> Looks like it's better but now it crashed during your test :)
> 
> https://tbpl.mozilla.org/php/getParsedLog.php?id=45976430&tree=Try#error0

Hmm. This issue appears to be caused by yet another thing that does not fail locally. Something has been causing the tests in test_logshake to take significantly longer than they should (30 seconds for a couple function calls and event passes)
Flags: needinfo?(jhobin)
(In reply to Alexandre LISSY :gerard-majax from comment #90)
> (In reply to jhobin from comment #89)
> > (In reply to Alexandre LISSY :gerard-majax from comment #88)
> > > (In reply to Gregor Wagner [:gwagner] from comment #87)
> > > > try run:
> > > > https://tbpl.mozilla.org/?tree=Try&rev=efb40867646c
> > > 
> > > This is not passing.
> > > 
> > > https://tbpl.mozilla.org/php/getParsedLog.php?id=45916081&tree=Try
> > 
> > This appears to be a difference between the emulator and the physical Flame
> > device.
> > 
> > I modified the test slightly to reflect that /dev/log/system is not
> > guaranteed to exist.
> > 
> > A new try build is available at
> > https://tbpl.mozilla.org/?tree=Try&rev=e74caeede310
> 
> Looks like it's better but now it crashed during your test :)
> 
> https://tbpl.mozilla.org/php/getParsedLog.php?id=45976430&tree=Try#error0

I fixed this and am running the tests at https://tbpl.mozilla.org/?tree=Try&rev=f67c7767c44d where they appear to be passing (modulo intermittent failures by other tests)
This is the patch running on Try right now. I'm flagging it for review because LogShake.jsm and settings.js both have rather significant changes (that being said, it passes tests and works on my device).

I am now officially out of Die Hard movies to base the patch names off of, apparently Die Hardest is the name of the one in pre-production right now.
Attachment #8468648 - Attachment is obsolete: true
Attachment #8477519 - Flags: review?(lissyx+mozillians)
Attachment #8477519 - Flags: review?(anygregor)
Comment on attachment 8477519 [details] [diff] [review]
Gecko-side implementation: Gecko Hardest

Review of attachment 8477519 [details] [diff] [review]:
-----------------------------------------------------------------

::: b2g/chrome/content/settings.js
@@ +513,4 @@
>    });
>  })();
>  
> +#ifdef MOZ_WIDGET_GONK

Why are you moving this code there?
James, would you mind explaining the changes you had to do ?
Flags: needinfo?(hobinjk)
The changes were made to simplify the interaction with the settings database. Previously I was directly querying through settingsService and observing changes through Services.obs. By using settings.js (like the existing devtools DeveloperHUD), I was able to remove all of that low-level logic and transfer it to the proven implementation of SettingsListener. This also fixed the test timeout which was caused by settingsService misbehaving in xpcshell tests due to not honoring the xpcom-shutdown event.
Flags: needinfo?(hobinjk)
Attachment #8477519 - Flags: review?(lissyx+mozillians) → review+
Attachment #8477519 - Flags: review?(anygregor)
checkin-needed for gecko parts. Gaia parts already landed.
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/780b3083916c

Please fix your hg configuration so that your patches are created with the proper metadata (i.e. your name).
Status: NEW → RESOLVED
Closed: 10 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → 2.1 S4 (12sep)
Depends on: 1067329
Depends on: 1079758
Blocks: 1067329
No longer depends on: 1067329
Blocks: 1079760
Depends on: 1079763
Blocks: 1079322
Blocks: 1092074
Blocks: 1103958
Depends on: 1093108
Chris, now that this feature is baked enough, I think it's worth documenting it somewhere on MDN for B2G users/dogfooders/QA.
Flags: needinfo?(cmills)
Keywords: dev-doc-needed
(In reply to Alexandre LISSY :gerard-majax from comment #101)
> Chris, now that this feature is baked enough, I think it's worth documenting
> it somewhere on MDN for B2G users/dogfooders/QA.

I've added a description of this option at 

https://developer.mozilla.org/en-US/Firefox_OS/Debugging/Developer_settings#Shake_to_save_system_log.

and here:

https://developer.mozilla.org/en-US/Firefox_OS/Debugging/On-device_console_logging

But is this
Flags: needinfo?(cmills)
Ooops, I meant "is this ok?" ;-)
(In reply to Chris Mills (Mozilla, MDN editor) [:cmills] from comment #103)
> Ooops, I meant "is this ok?" ;-)

It's ok for me, except that we have this on 2.2, not 2.1 :).

Maybe it's worth to document that we dump in sdcard's logs/<datetime>
(In reply to Alexandre LISSY :gerard-majax from comment #104)
> (In reply to Chris Mills (Mozilla, MDN editor) [:cmills] from comment #103)
> > Ooops, I meant "is this ok?" ;-)
> 
> It's ok for me, except that we have this on 2.2, not 2.1 :).

Oops, fixed.

> 
> Maybe it's worth to document that we dump in sdcard's logs/<datetime>

I've mentioned this too, in both places.
Depends on: 1119290
Depends on: 1119294
Depends on: 1125989
Blocks: 1127782
Depends on: 1137659
blocking-b2g: backlog → ---
Depends on: 1173777
Depends on: 1173782
Depends on: 1184476
You need to log in before you can comment on or make changes to this bug.