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 bug reporting logic #3000

Merged
merged 20 commits into from Jan 25, 2017

Conversation

@Kegsay
Copy link
Contributor

Kegsay commented Jan 19, 2017

The aim of this PR is to implement all the logic behind storing console logs and sending them to a remote endpoint. It does not handle any of the UI surrounding this yet, in attempts to keep the size of this PR down.

This PR:

  • Store console logs in-memory by monkey-patching console.
  • Periodically flush logs to IndexedDB if available.
  • Purge logs on startup (refresh) if they exceed a certain size (currently 50MB).
  • POST logs to a configured endpoint along with some input text.

This PR does not:

  • Have any UI for people to send bug reports.
Kegsay added 6 commits Jan 18, 2017
- Fetches all logs in order and concatenates correctly.
- Purges old logs correctly.
@Kegsay Kegsay added the feature label Jan 19, 2017
Kegsay added 4 commits Jan 19, 2017
Since we do in fact support coroutines!
@Kegsay Kegsay changed the title WIP: Implement bug reporting logic Implement bug reporting logic Jan 19, 2017
@Kegsay

This comment has been minimized.

Copy link
Contributor Author

Kegsay commented Jan 19, 2017

Failing test has nothing to do with this PR AFAICT:

�[1A�[2KPhantomJS 2.1.1 (Linux 0.0.0) loading: MatrixClient rehydrated from stored credentials: shows a directory by default if we have no joined rooms FAILED
	Did not find exactly one match (found: 0) for tag:a
	findRenderedDOMComponentWithTag@/home/travis/build/vector-im/riot-web/test/all-tests.js:170402:109 <- webpack:///~/react-dom/lib/ReactTestUtils.js:211:0
	assertAtSyncingSpinner@/home/travis/build/vector-im/riot-web/test/all-tests.js:171545:85 <- webpack:///test/app-tests/loading.js:458:8
	/home/travis/build/vector-im/riot-web/test/all-tests.js:171343:40 <- webpack:///test/app-tests/loading.js:248:39
	_fulfilled@/home/travis/build/vector-im/riot-web/test/all-tests.js:7562:64 <- webpack:///~/q/q.js:834:0
	/home/travis/build/vector-im/riot-web/test/all-tests.js:7591:41 <- webpack:///~/q/q.js:863:0
	promiseDispatch@/home/travis/build/vector-im/riot-web/test/all-tests.js:7524:21 <- webpack:///~/q/q.js:796:0
	/home/travis/build/vector-im/riot-web/test/all-tests.js:7332:50 <- webpack:///~/q/q.js:604:0
	runSingle@/home/travis/build/vector-im/riot-web/test/all-tests.js:6865:18 <- webpack:///~/q/q.js:137:0
	flush@/home/travis/build/vector-im/riot-web/test/all-tests.js:6853:23 <- webpack:///~/q/q.js:125:0
	exports@/home/travis/build/vector-im/riot-web/node_modules/babel-polyfill/browser.js:1:13227
	/home/travis/build/vector-im/riot-web/node_modules/babel-polyfill/browser.js:1:55659
	b@/home/travis/build/vector-im/riot-web/node_modules/babel-polyfill/browser.js:1:27864
	x@/home/travis/build/vector-im/riot-web/node_modules/babel-polyfill/browser.js:1:55529
PhantomJS 2.1.1 (Linux 0.0.0): Executed 11 of 16 (1 FAILED) (0 secs / 0.523 secs)

and is also failing on other PRs, so I think can be disregarded. This has been failing since at least as far back as the last release: https://travis-ci.org/vector-im/riot-web/builds/191602911

import PlatformPeg from 'matrix-react-sdk/lib/PlatformPeg';
import request from "browser-request";

// This module contains all the code needed to log the console, persist it to disk and submit bug reports. Rationale is as follows:

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 19, 2017

Member

I'm not super-excited by whatever you have your fill-column set to, if only because github doesn't show it without scrolling.

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

Pick a number for me to wrap then.

This comment has been minimized.

Copy link
@richvdh

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

Done.

Copy link
Member

richvdh left a comment

I've probably missed some things, but here is some stuff to go on with


log(level, ...args) {
// We don't know what locale the user may be running so use ISO strings
const ts = new Date().toISOString();

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 19, 2017

Member

how about using UTC?

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

Err, sure if you want that. You do realise toUTCString() logs as:

Mon, 03 Jul 2006 21:44:38 GMT

right? I don't think you really want to know the day of the week and the 3 letter timezone for every log line. ISO logs as:

2017-01-20T11:13:40.389Z

which is more "log-like", but I'm doing this mainly for you so I defer to whatever you want.

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 20, 2017

Member

sorry, I had assumed that toISOString used localtime. Looks like that was wrong. Ignore me.

constructor() {
this.logs = "";

// Monkey-patch console logging

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 19, 2017

Member

doing this here would prevent a ConsoleLogger ever being instantiated in a test env, or having more than one of them for some reason, or whatever. Feels like the monkey-patching should be done in init. (Possibly via a logger.monkeyPatch(window.console) call, but that's unimportant)

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

doing this here would prevent a ConsoleLogger ever being instantiated in a test env

Test environments have a console global afaik.

having more than one of them for some reason

It will just wrap the previous console logger in that case.

Feels like the monkey-patching should be done in init. (Possibly via a logger.monkeyPatch(window.console) call

Sure, that sounds nicer.

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

Done.

// so the lines are a little more ugly but easy to implement / quick to run.
// Example line:
// 2017-01-18T11:23:53.214Z W Failed to set badge count: Error setting badge. Message: Too many badges requests in queue.
const line = `${ts} ${level} ${args.join(' ')}\n`;

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 19, 2017

Member

sooooo

when you console.log an Object, Chome/Firefox allow you to expand said object. In places I've relied on that ability. We could perhaps achieve something similar by JSON.stringifying arguments.

otoh, that would then break if we tried to log a circular structure, and I think it would be reasonable to say that if we care about the contents of the console.log params, the caller should be doing the JSON.stringifying.

wdyt?

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

Agreed. I thought about it and came to the conclusion that if the caller cares enough about something, they should log it specifically rather than rely on browser-specific expandy bits (which also subtly break if you accidentally do string concatenation when logging).

flush() {
// The ConsoleLogger doesn't care how these end up on disk, it just flushes them to the caller.
const logsToFlush = this.logs;
this.logs = "";

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 19, 2017

Member

uh. there's a sadness if the caller fails to actually write the logs.

I guess giving this proper transactional semantics is a pita though, and probably not worth it.

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

That was basically my thinking :(

*
* @param {boolean} clearAll True to clear the most recent logs returned in addition to the
* older logs. This is desirable when sending bug reports as we do not want to submit the
* same logs twice. This is not desirable when doing house-keeping at startup in case they

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 19, 2017

Member

uh, why not? I don't really want to have to piece together different rageshakes to establish history,

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

I don't follow. At startup, all we want to do is clear old logs, not all logs since we're just doing housekeeping. When rageshakes are submitted, we want to clear all logs because otherwise you'll get duplicates if they submit a 2nd or 3rd bug report.

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 20, 2017

Member

Yes. I'm saying I'd like those duplicates in the 2nd and 3rd bug report.

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

Oh! Okay then, I'll modify it accordingly.

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

Done.

size += lines.length;
if (size > MAX_LOG_SIZE) {
// the remaining log IDs should be removed. If we go out of bounds this is just []
removeLogIds = allLogIds.slice(i + 1);

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 19, 2017

Member

I think we're deleting here based on the time the tab was opened - so we'll delete the logs from long-running tabs which are still logging in preference to tabs which were opened briefly a long time ago. This is a bit sadpanda.

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

Hmm. I can add a last modified timestamp to each chunk and sort based on that, but I cannot easily query IndexedDB to work out which log IDs that will then correspond to, because they aren't keyed off that.

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 20, 2017

Member

can we not store a last-modified time per-log-ID?

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

I guess I can denormalise the data a bit and store a tuple of last-modified-time and log ID in a separate object store, and then just query that when working out which logs to send. This is a bit of an architectural change, but I agree this sounds better.

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

Done.

// the in-memory console logs.
let logs = [];
if (store) {
logs = await store.consume(true);

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 19, 2017

Member

how can we be sure that this won't race against a flush process, leading to duplicate or missing log lines?

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

I don't really intend for flush() to ever be called outside this class, so it's dubious as to whether I should keep it in or not. You can never get duplicates because flush() wipes the ConsoleLogger.logs so only one function will win at getting the logs. It's possible that if rageshake.flush() is called and then sendBugReport() is called and store.consume() finishes before rageshake.flush() does, that you can get a missing chunk. Will guard.

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 20, 2017

Member

I don't really intend for flush() to ever be called outside this class, so it's dubious as to whether I should keep it in or not.

ya, but either way, flush() gets called on a timer. I think you're right that we can't get dups, but we can certainly get missing chunks.

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 20, 2017

Member

I think it's worth worrying about the races. I don't want to be poring over some logs and wondering if missing/duplicate lines are due to a problem in the app or the crashdump framework.

How about forcing a flush-to-db on rageshake, and then taking all of the logs for the rageshake from the DB? (with a completely different codepath for the no-indexdb case). I feel like that would be easier to reason about.

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

How about forcing a flush-to-db on rageshake, and then taking all of the logs for the rageshake from the DB? (with a completely different codepath for the no-indexdb case). I feel like that would be easier to reason about.

Can you please give a bit more information on what you would like? So only read from the database, and force a flush on submitting a bug report?

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 20, 2017

Author Contributor

Done.

@richvdh richvdh assigned Kegsay and unassigned richvdh Jan 19, 2017
Kegsay added 5 commits Jan 20, 2017
This makes it easier to get a list of all the log IDs. It also makes it possible
to order the logs by the *LAST* log line and not the first as was the case
previously, which is important in the case of long-running tabs.
@Kegsay

This comment has been minimized.

Copy link
Contributor Author

Kegsay commented Jan 20, 2017

Eurgh. Two problems:

  • The Chrome developer console is now giving the wrong file/line numbers due to monkey-patching console. The file/line is always the same line in rageshake.js.

  • Something is causing the tab to die/segfault in Chrome with:

    Aw Snap!
    Something went wrong whilst displaying this web page.
    

    I've tried not monkey patching console and it still dies. Not calling init() and cleanup() seems to fix it... Hm.

Copy link
Member

richvdh left a comment

lgtm otherwise.

});
else {
logs.push({
lines: logger.flush(),

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 20, 2017

Member

this wouldn't destroy the store, ideally.

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 23, 2017

Author Contributor

Done.

@richvdh

This comment has been minimized.

Copy link
Member

richvdh commented Jan 20, 2017

The Chrome developer console is now giving the wrong file/line numbers due to monkey-patching console. The file/line is always the same line in rageshake.js.

Hum. Yes. Can't think of a way around that. You can do some interesting hacks with binding console.log (for instance, you can bind it to a property with a getter that returns console), but I can't think of a way to actually use that.

Aw Snap! Something went wrong whilst displaying this web page.

Something to do with indexeddb, then?

Kegsay added 3 commits Jan 23, 2017
The promise would resolve immediately, nulling out `flushPromise`. This would
then immediately be set from `new Promise((resolve, reject) => {...})` turning
it back into non-null `flushPromise`. The resolve handler was called so the
next `flush()` would see "oh yes, there is a non-null `flushPromise`" then
promptly try to set `flushAgainPromise` which chains off the resolved
`flushPromise` which relied on `flushPromise` being `null`ed out after
`resolve()`, causing the chained `flush()` to see "oh yes, there is a non-null
`flushPromise`" which... ad infinitum.

This PR fixes it by making the nulling out asynchronous but the fact it took
me this long to debug this issue indicates to me that this is a terrible piece
of code. Will re-write.
@Kegsay

This comment has been minimized.

Copy link
Contributor Author

Kegsay commented Jan 24, 2017

@richvdh PTAL

AFAIK the only outstanding thing is:

The Chrome developer console is now giving the wrong file/line numbers due to monkey-patching console. The file/line is always the same line in rageshake.js.

Hum. Yes. Can't think of a way around that. You can do some interesting hacks with binding console.log (for instance, you can bind it to a property with a getter that returns console), but I can't think of a way to actually use that.

Not sure what I can do about that.

@richvdh richvdh assigned richvdh and unassigned Kegsay Jan 24, 2017
@@ -16,6 +16,7 @@ limitations under the License.

import PlatformPeg from 'matrix-react-sdk/lib/PlatformPeg';
import request from "browser-request";
import q from "q";

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 24, 2017

Member

/me kills some puppies

Copy link
Member

richvdh left a comment

still some questions

@@ -101,17 +106,14 @@ class IndexedDBLogStore {
this.db = null;
// Promise is not null when a flush is IN PROGRESS

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 24, 2017

Member

this looks slightly misleading - I think it is never reset to null?

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 24, 2017

Author Contributor

Oops, that was true previously, but not now. Fixing.

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 24, 2017

Author Contributor

Done.

// that a complete flush() is done. This does mean that if there are
// 3 calls to flush() in one go, the 2nd and 3rd promises will run
// concurrently, but this is fine since they can safely race when
// collecting logs.

This comment has been minimized.

Copy link
@richvdh

richvdh Jan 24, 2017

Member

can they? Isn't there a danger of getting the logs out-of-order when writing to the db?

... and if we're happy for flushes to run concurrently, why do we bother with this.flushPromise at all? Why not always start a new flush?

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 24, 2017

Author Contributor

OH, you're right. You can get out of order logs, but you won't lose/get duplicate data which is what I was originally focussing on when fixing this. Will fix.

This comment has been minimized.

Copy link
@Kegsay

Kegsay Jan 24, 2017

Author Contributor

Done.

@richvdh richvdh assigned Kegsay and unassigned richvdh Jan 24, 2017
@Kegsay Kegsay referenced this pull request Jan 24, 2017
@Kegsay

This comment has been minimized.

Copy link
Contributor Author

Kegsay commented Jan 24, 2017

Right, this should do it.

@Kegsay Kegsay assigned richvdh and unassigned Kegsay Jan 24, 2017
Copy link
Member

richvdh left a comment

lgtm

@Kegsay Kegsay merged commit 80c1ec0 into develop Jan 25, 2017
2 checks passed
2 checks passed
continuous-integration/travis-ci/pr The Travis CI build passed
Details
continuous-integration/travis-ci/push The Travis CI build passed
Details
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
2 participants
You can’t perform that action at this time.