Improve logging by displaying more relevant details and additional arguments

[jayohms]

The current debug logging is insufficient to understand what's going on behind the scenes and investigate issues. This is a step in the right direction.

Previous log output:

2022-06-30 03:29:06 +0000 - [ColdBootVisit] startVisit()
2022-06-30 03:29:07 +0000 - [Bridge] ← pageLoaded
2022-06-30 03:29:09 +0000 - [Bridge] ← visitProposed
2022-06-30 03:29:09 +0000 - [JavaScriptVisit] startVisit()
2022-06-30 03:29:09 +0000 - [Bridge] → window.turboNative.visitLocationWithOptionsAndRestorationIdentifier
2022-06-30 03:29:09 +0000 - [Bridge] ← visitStarted
2022-06-30 03:29:09 +0000 - [JavaScriptVisit] webView(_:didStartVisitWithIdentifier:hasCachedSnapshot:)
2022-06-30 03:29:09 +0000 - [Bridge] ← visitRequestStarted
2022-06-30 03:29:09 +0000 - [JavaScriptVisit] webView(_:didStartRequestForVisitWithIdentifier:date:)
2022-06-30 03:29:09 +0000 - [Bridge] = window.turboNative.visitLocationWithOptionsAndRestorationIdentifier evaluation complete
2022-06-30 03:29:09 +0000 - [Bridge] ← visitRequestFinished
2022-06-30 03:29:09 +0000 - [JavaScriptVisit] webView(_:didFinishRequestForVisitWithIdentifier:date:)
2022-06-30 03:29:09 +0000 - [Bridge] ← visitRequestCompleted
2022-06-30 03:29:09 +0000 - [JavaScriptVisit] webView(_:didCompleteRequestForVisitWithIdentifier:)
2022-06-30 03:29:09 +0000 - [Bridge] ← visitCompleted
2022-06-30 03:29:09 +0000 - [JavaScriptVisit] webView(_:didCompleteVisitWithIdentifier:restorationIdentifier:)
2022-06-30 03:29:09 +0000 - [Bridge] ← visitRendered
2022-06-30 03:29:09 +0000 - [JavaScriptVisit] webView(_:didRenderForVisitWithIdentifier:)
2022-06-30 03:29:11 +0000 - [JavaScriptVisit] startVisit()
2022-06-30 03:29:11 +0000 - [Bridge] → window.turboNative.visitLocationWithOptionsAndRestorationIdentifier
2022-06-30 03:29:11 +0000 - [Bridge] ← visitStarted
2022-06-30 03:29:11 +0000 - [JavaScriptVisit] webView(_:didStartVisitWithIdentifier:hasCachedSnapshot:)
2022-06-30 03:29:11 +0000 - [Bridge] = window.turboNative.visitLocationWithOptionsAndRestorationIdentifier evaluation complete
2022-06-30 03:29:11 +0000 - [Bridge] ← visitCompleted
2022-06-30 03:29:11 +0000 - [JavaScriptVisit] webView(_:didCompleteVisitWithIdentifier:restorationIdentifier:)
2022-06-30 03:29:11 +0000 - [Bridge] ← visitRendered
2022-06-30 03:29:11 +0000 - [JavaScriptVisit] webView(_:didRenderForVisitWithIdentifier:)

New log output:

2022-06-30 03:30:11 +0000 [Session] visit ["reload": false, "location": https://turbo-native-demo.glitch.me, "options": Turbo.VisitOptions(action: Turbo.VisitAction.replace, response: nil)]
2022-06-30 03:30:11 +0000 [ColdBootVisit] startVisit https://turbo-native-demo.glitch.me [:]
2022-06-30 03:30:12 +0000 [Bridge] ← pageLoaded ["timestamp": 1656559812055, "restorationIdentifier": 42918dac-ca08-4d87-ae88-d866b21e9e14] [:]
2022-06-30 03:30:12 +0000 [ColdBootVisit] completeVisit https://turbo-native-demo.glitch.me [:]
2022-06-30 03:30:18 +0000 [Bridge] ← visitProposed ["location": https://turbo-native-demo.glitch.me/one, "options": {
    action = advance;
}, "timestamp": 1656559818238] [:]
2022-06-30 03:30:18 +0000 [Session] visit ["options": Turbo.VisitOptions(action: Turbo.VisitAction.advance, response: nil), "location": https://turbo-native-demo.glitch.me/one, "reload": false]
2022-06-30 03:30:18 +0000 [JavascriptVisit] startVisit https://turbo-native-demo.glitch.me/one [:]
2022-06-30 03:30:18 +0000 [Bridge] → window.turboNative.visitLocationWithOptionsAndRestorationIdentifier [Optional("https://turbo-native-demo.glitch.me/one"), Optional({
    action = advance;
}), nil] [:]
2022-06-30 03:30:18 +0000 [Bridge] ← visitStarted ["identifier": 6cd858b3-5a0c-4695-a5b0-48597a97ea1c, "hasCachedSnapshot": 0, "timestamp": 1656559818246] [:]
2022-06-30 03:30:18 +0000 [JavascriptVisit] didStartVisitWithIdentifier https://turbo-native-demo.glitch.me/one ["identifier": "6cd858b3-5a0c-4695-a5b0-48597a97ea1c", "hasCachedSnapshot": false]
2022-06-30 03:30:18 +0000 [Bridge] ← visitRequestStarted ["identifier": 6cd858b3-5a0c-4695-a5b0-48597a97ea1c, "timestamp": 1656559818248] [:]
2022-06-30 03:30:18 +0000 [JavascriptVisit] didFinishRequestForVisitWithIdentifier https://turbo-native-demo.glitch.me/one ["identifier": "6cd858b3-5a0c-4695-a5b0-48597a97ea1c", "date": 2022-06-30 03:30:18 +0000]
2022-06-30 03:30:18 +0000 [Bridge] = window.turboNative.visitLocationWithOptionsAndRestorationIdentifier evaluation complete [:]
2022-06-30 03:30:18 +0000 [Bridge] ← visitRequestCompleted ["identifier": 6cd858b3-5a0c-4695-a5b0-48597a97ea1c, "timestamp": 1656559818344] [:]
2022-06-30 03:30:18 +0000 [JavascriptVisit] didCompleteRequestForVisitWithIdentifier https://turbo-native-demo.glitch.me/one ["identifier": "6cd858b3-5a0c-4695-a5b0-48597a97ea1c"]
2022-06-30 03:30:18 +0000 [Bridge] ← visitRequestFinished ["identifier": 6cd858b3-5a0c-4695-a5b0-48597a97ea1c, "timestamp": 1656559818344] [:]
2022-06-30 03:30:18 +0000 [JavascriptVisit] didFinishRequestForVisitWithIdentifier https://turbo-native-demo.glitch.me/one ["identifier": "6cd858b3-5a0c-4695-a5b0-48597a97ea1c", "date": 2022-06-30 03:30:18 +0000]
2022-06-30 03:30:18 +0000 [Bridge] ← visitCompleted ["identifier": 6cd858b3-5a0c-4695-a5b0-48597a97ea1c, "restorationIdentifier": 4904de48-531e-42ec-b9e2-6ec8304108a9, "timestamp": 1656559818347] [:]
2022-06-30 03:30:18 +0000 [JavascriptVisit] didCompleteVisitWithIdentifier https://turbo-native-demo.glitch.me/one ["identifier": "6cd858b3-5a0c-4695-a5b0-48597a97ea1c", "restorationIdentifier": "4904de48-531e-42ec-b9e2-6ec8304108a9"]
2022-06-30 03:30:18 +0000 [Bridge] ← visitRendered ["identifier": 6cd858b3-5a0c-4695-a5b0-48597a97ea1c, "timestamp": 1656559818366] [:]
2022-06-30 03:30:18 +0000 [JavascriptVisit] didRenderForVisitWithIdentifier https://turbo-native-demo.glitch.me/one ["identifier": "6cd858b3-5a0c-4695-a5b0-48597a97ea1c"]
2022-06-30 03:30:20 +0000 [Session] visit ["location": https://turbo-native-demo.glitch.me, "options": Turbo.VisitOptions(action: Turbo.VisitAction.restore, response: nil), "reload": false]
2022-06-30 03:30:20 +0000 [JavascriptVisit] startVisit https://turbo-native-demo.glitch.me [:]
2022-06-30 03:30:20 +0000 [Bridge] → window.turboNative.visitLocationWithOptionsAndRestorationIdentifier [Optional("https://turbo-native-demo.glitch.me"), Optional({
    action = restore;
}), Optional("42918dac-ca08-4d87-ae88-d866b21e9e14")] [:]
2022-06-30 03:30:20 +0000 [Bridge] ← visitStarted ["identifier": a966548e-8e36-4b39-a039-e4a03ec27734, "hasCachedSnapshot": 1, "timestamp": 1656559820532] [:]
2022-06-30 03:30:20 +0000 [JavascriptVisit] didStartVisitWithIdentifier https://turbo-native-demo.glitch.me ["hasCachedSnapshot": true, "identifier": "a966548e-8e36-4b39-a039-e4a03ec27734"]
2022-06-30 03:30:20 +0000 [Bridge] = window.turboNative.visitLocationWithOptionsAndRestorationIdentifier evaluation complete [:]
2022-06-30 03:30:20 +0000 [Bridge] ← visitCompleted ["restorationIdentifier": 42918dac-ca08-4d87-ae88-d866b21e9e14, "identifier": a966548e-8e36-4b39-a039-e4a03ec27734, "timestamp": 1656559820533] [:]
2022-06-30 03:30:20 +0000 [JavascriptVisit] didCompleteVisitWithIdentifier https://turbo-native-demo.glitch.me ["restorationIdentifier": "42918dac-ca08-4d87-ae88-d866b21e9e14", "identifier": "a966548e-8e36-4b39-a039-e4a03ec27734"]
2022-06-30 03:30:20 +0000 [Bridge] ← visitRendered ["identifier": a966548e-8e36-4b39-a039-e4a03ec27734, "timestamp": 1656559820549] [:]
2022-06-30 03:30:20 +0000 [JavascriptVisit] didRenderForVisitWithIdentifier https://turbo-native-demo.glitch.me ["identifier": "a966548e-8e36-4b39-a039-e4a03ec27734"]

[jayohms]

This work helped me expose some underlying issues in #74
cc @joemasilotti @ghiculescu

[joemasilotti]

Ohh very nice. And chance we can disable logging, too? Like #21 or #67?

[jayohms]

@joemasilotti I'd prefer to start with a simple approach where we disable logging by default and apps can opt-in like Zach mentioned in #21. This would make it more similar to turbo-android and I think it strikes a nice balance. We should, however, enable logging in the Demo app to show an example.

[joemasilotti]

I agree that logging should be disabled by default. I think it should be disabled in the Demo app as well, but I feel less strongly about that.

Maybe the demo app could have a line of code to uncomment to re-enable logging?

[joemasilotti]

FWIW, I could update #21 to use the reverse logic and only log when that environment variable is set. Let me know!

[jayohms]

@joemasilotti yes, please do 👍

[joemasilotti]

Done!