Skip to content

Commit

Permalink
Merge pull request #1014 from bugsnag/nickdowell/fix-app-duration
Browse files Browse the repository at this point in the history 
[PLAT-6134] Fix inaccurate app.duration values
  • Loading branch information
@nickdowell
nickdowell authored Mar 1, 2021
2 parents 3717866 + 9788c93 commit c00cd12
Show file tree
Hide file tree
Showing 10 changed files with 78 additions and 12 deletions.
5 changes: 3 additions & 2 deletions Bugsnag/KSCrash/Source/KSCrash/Recording/BSG_KSCrashC.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -150,8 +150,9 @@ void bsg_kscrash_reinstall(const char *const crashReportFilePath,
if (!bsg_kscrashstate_init(bsg_g_stateFilePath, &context->state)) {
BSG_KSLOG_ERROR("Failed to initialize persistent crash state");
}
context->state.appLaunchTime = mach_absolute_time();
context->state.appStateTransitionTime = mach_absolute_time();
uint64_t timeNow = mach_absolute_time();
context->state.appLaunchTime = timeNow;
context->state.lastUpdateDurationsTime = timeNow;
}

BSG_KSCrashType bsg_kscrash_setHandlingCrashTypes(BSG_KSCrashType crashTypes) {
Expand Down
6 changes: 3 additions & 3 deletions Bugsnag/KSCrash/Source/KSCrash/Recording/BSG_KSCrashState.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -75,9 +75,9 @@ typedef struct {
/** Timestamp for when the app was launched (mach_absolute_time()) */
uint64_t appLaunchTime;

/** Timestamp for when the app state was last changed
* (background<->foreground) (mach_absolute_time()) */
uint64_t appStateTransitionTime;
/** Timestamp for when foregroundDurationSinceLastCrash or
* backgroundDurationSinceLastCrash was last updated (mach_absolute_time()) */
uint64_t lastUpdateDurationsTime;

/** If true, the application is currently in the foreground. */
bool applicationIsInForeground;
Expand Down
12 changes: 7 additions & 5 deletions Bugsnag/KSCrash/Source/KSCrash/Recording/BSG_KSCrashState.m
View file
Original file line number Diff line number Diff line change
Expand Up @@ -194,7 +194,7 @@ bool bsg_kscrashstate_i_loadState(BSG_KSCrash_State *const context,
context->foregroundDurationSinceLastCrash = [objectContext[@"foregroundDurationSinceLastCrash"] doubleValue];
context->foregroundDurationSinceLaunch = [objectContext[@"foregroundDurationSinceLaunch"] doubleValue];
context->appLaunchTime = [objectContext[@"appLaunchTime"] unsignedLongLongValue];
context->appStateTransitionTime = [objectContext[@"appStateTransitionTime"] unsignedLongLongValue];
context->lastUpdateDurationsTime = [objectContext[@"appStateTransitionTime"] unsignedLongLongValue];
context->launchesSinceLastCrash = [objectContext[@"launchesSinceLastCrash"] intValue];
context->sessionsSinceLastCrash = [objectContext[@"sessionsSinceLastCrash"] intValue];
context->sessionsSinceLaunch = [objectContext[@"sessionsSinceLaunch"] intValue];
Expand Down Expand Up @@ -322,7 +322,7 @@ void bsg_kscrashstate_notifyAppInForeground(const bool isInForeground) {
state->applicationIsInForeground = isInForeground;
uint64_t timeNow = mach_absolute_time();
double duration = bsg_ksmachtimeDifferenceInSeconds(
timeNow, state->appStateTransitionTime);
timeNow, state->lastUpdateDurationsTime);
if (isInForeground) {
state->backgroundDurationSinceLaunch += duration;
state->backgroundDurationSinceLastCrash += duration;
Expand All @@ -333,15 +333,15 @@ void bsg_kscrashstate_notifyAppInForeground(const bool isInForeground) {
state->foregroundDurationSinceLastCrash += duration;
bsg_kscrashstate_i_saveState(state, stateFilePath);
}
state->appStateTransitionTime = timeNow;
state->lastUpdateDurationsTime = timeNow;
}

void bsg_kscrashstate_notifyAppTerminate(void) {
BSG_KSCrash_State *const state = bsg_g_state;
const char *const stateFilePath = bsg_g_stateFilePath;

const double duration = bsg_ksmachtimeDifferenceInSeconds(
mach_absolute_time(), state->appStateTransitionTime);
mach_absolute_time(), state->lastUpdateDurationsTime);
state->backgroundDurationSinceLastCrash += duration;
bsg_kscrashstate_i_saveState(state, stateFilePath);
}
Expand All @@ -358,15 +358,17 @@ void bsg_kscrashstate_notifyAppCrash(BSG_KSCrashType type) {
}

void bsg_kscrashstate_updateDurationStats(BSG_KSCrash_State *const state) {
uint64_t timeNow = mach_absolute_time();
const double duration = bsg_ksmachtimeDifferenceInSeconds(
mach_absolute_time(), state->appStateTransitionTime);
timeNow, state->lastUpdateDurationsTime ?: state->appLaunchTime);
if (state->applicationIsInForeground) {
state->foregroundDurationSinceLaunch += duration;
state->foregroundDurationSinceLastCrash += duration;
} else {
state->backgroundDurationSinceLaunch += duration;
state->backgroundDurationSinceLastCrash += duration;
}
state->lastUpdateDurationsTime = timeNow;
}

const BSG_KSCrash_State *bsg_kscrashstate_currentState(void) {
Expand Down
4 changes: 2 additions & 2 deletions Bugsnag/Payload/BugsnagAppWithState.m
View file
Original file line number Diff line number Diff line change
Expand Up @@ -71,8 +71,8 @@ + (BugsnagAppWithState *)appWithDictionary:(NSDictionary *)event
NSDictionary *stats = system[@"application_stats"];

// convert from seconds to milliseconds
NSNumber *activeTimeSinceLaunch = @([stats[@"active_time_since_launch"] longValue] * 1000);
NSNumber *backgroundTimeSinceLaunch = @([stats[@"background_time_since_launch"] longValue] * 1000);
NSNumber *activeTimeSinceLaunch = @((int)([stats[@"active_time_since_launch"] doubleValue] * 1000.0));
NSNumber *backgroundTimeSinceLaunch = @((int)([stats[@"background_time_since_launch"] doubleValue] * 1000.0));

app.durationInForeground = activeTimeSinceLaunch;
app.duration = @([activeTimeSinceLaunch longValue] + [backgroundTimeSinceLaunch longValue]);
Expand Down
3 changes: 3 additions & 0 deletions CHANGELOG.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,9 @@ Changelog

### Bug fixes

* Fix inaccurate `app.duration` after multiple calls to `notify()`
[#1014](https://github.com/bugsnag/bugsnag-cocoa/pull/1014)

* Fix a possible deadlock when writing crash reports for unhandled errors.
[#1013](https://github.com/bugsnag/bugsnag-cocoa/pull/1013)

Expand Down
9 changes: 9 additions & 0 deletions features/app_and_device_attributes.feature
View file
Original file line number Diff line number Diff line change
Expand Up @@ -79,3 +79,12 @@ Feature: App and Device attributes present
And the error payload field "events.0.app.releaseStage" equals "thirdStage"
And the error payload field "events.0.device.manufacturer" equals "Nokia"
And the error payload field "events.0.device.modelNumber" equals "0898"

Scenario: Duration value increments as expected
When I run "AppDurationScenario"
And I wait to receive 3 errors
And the event "app.duration" is between 0 and 200
And I discard the oldest error
And the event "app.duration" is between 2600 and 2800
And I discard the oldest error
And the event "app.duration" is between 5400 and 5600
4 changes: 4 additions & 0 deletions features/fixtures/ios-swift-cocoapods/iOSTestApp.xcodeproj/project.pbxproj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@
0104085F258CA0A100933C60 /* DispatchCrashScenario.swift in Sources */ = {isa = PBXBuildFile; fileRef = 0104085E258CA0A100933C60 /* DispatchCrashScenario.swift */; };
0163BFA72583B3CF008DC28B /* DiscardClassesScenarios.swift in Sources */ = {isa = PBXBuildFile; fileRef = 0163BFA62583B3CF008DC28B /* DiscardClassesScenarios.swift */; };
01AF6A53258A112F00FFC803 /* BareboneTestScenarios.swift in Sources */ = {isa = PBXBuildFile; fileRef = 01AF6A52258A112F00FFC803 /* BareboneTestScenarios.swift */; };
01E0DB0B25E8EBD100A740ED /* AppDurationScenario.swift in Sources */ = {isa = PBXBuildFile; fileRef = 01E0DB0A25E8EBD100A740ED /* AppDurationScenario.swift */; };
01E5EAD225B713990066EA8A /* OOMScenario.m in Sources */ = {isa = PBXBuildFile; fileRef = 01E5EAD125B713990066EA8A /* OOMScenario.m */; };
6526A0D4248A83350002E2C9 /* LoadConfigFromFileAutoScenario.swift in Sources */ = {isa = PBXBuildFile; fileRef = 6526A0D3248A83350002E2C9 /* LoadConfigFromFileAutoScenario.swift */; };
8A14F0F62282D4AE00337B05 /* (null) in Sources */ = {isa = PBXBuildFile; };
Expand Down Expand Up @@ -168,6 +169,7 @@
0104085E258CA0A100933C60 /* DispatchCrashScenario.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = DispatchCrashScenario.swift; sourceTree = "<group>"; };
0163BFA62583B3CF008DC28B /* DiscardClassesScenarios.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = DiscardClassesScenarios.swift; sourceTree = "<group>"; };
01AF6A52258A112F00FFC803 /* BareboneTestScenarios.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = BareboneTestScenarios.swift; sourceTree = "<group>"; };
01E0DB0A25E8EBD100A740ED /* AppDurationScenario.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = AppDurationScenario.swift; sourceTree = "<group>"; };
01E5EAD025B713990066EA8A /* OOMScenario.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = OOMScenario.h; sourceTree = "<group>"; };
01E5EAD125B713990066EA8A /* OOMScenario.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = OOMScenario.m; sourceTree = "<group>"; };
4994F05E0421A0B037DD2CC5 /* Pods_iOSTestApp.framework */ = {isa = PBXFileReference; explicitFileType = wrapper.framework; includeInIndex = 0; path = Pods_iOSTestApp.framework; sourceTree = BUILT_PRODUCTS_DIR; };
Expand Down Expand Up @@ -560,6 +562,7 @@
F49695A3243EF7B600105DA9 /* OOMs */,
F49695AE2445476700105DA9 /* Plugin */,
0037410E2473CF2300BE41AA /* AppAndDeviceAttributesScenario.swift */,
01E0DB0A25E8EBD100A740ED /* AppDurationScenario.swift */,
01AF6A52258A112F00FFC803 /* BareboneTestScenarios.swift */,
0163BFA62583B3CF008DC28B /* DiscardClassesScenarios.swift */,
01E5EAD025B713990066EA8A /* OOMScenario.h */,
Expand Down Expand Up @@ -915,6 +918,7 @@
6526A0D4248A83350002E2C9 /* LoadConfigFromFileAutoScenario.swift in Sources */,
F4295A94DD2D131A594A212C /* HandledErrorScenario.swift in Sources */,
F4295A7AA9B4A18992A2F020 /* HandledErrorOverrideScenario.swift in Sources */,
01E0DB0B25E8EBD100A740ED /* AppDurationScenario.swift in Sources */,
E700EE62247D4D42008CFFB6 /* OnCrashHandlerScenario.m in Sources */,
E700EE48247D1158008CFFB6 /* UserEventOverrideScenario.swift in Sources */,
F429502603396F8671B333B3 /* HandledExceptionScenario.swift in Sources */,
Expand Down
4 changes: 4 additions & 0 deletions features/fixtures/macos/macOSTestApp.xcodeproj/project.pbxproj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@
017FBFB9254B09C300809042 /* MainWindowController.xib in Resources */ = {isa = PBXBuildFile; fileRef = 017FBFB7254B09C300809042 /* MainWindowController.xib */; };
01AF6A50258A00DE00FFC803 /* BareboneTestScenarios.swift in Sources */ = {isa = PBXBuildFile; fileRef = 01AF6A4F258A00DE00FFC803 /* BareboneTestScenarios.swift */; };
01AF6A84258BB38A00FFC803 /* DispatchCrashScenario.swift in Sources */ = {isa = PBXBuildFile; fileRef = 01AF6A83258BB38A00FFC803 /* DispatchCrashScenario.swift */; };
01E0DB0625E8E95700A740ED /* AppDurationScenario.swift in Sources */ = {isa = PBXBuildFile; fileRef = 01E0DB0425E8E90500A740ED /* AppDurationScenario.swift */; };
01ECBCF425A7522000FC0678 /* OnErrorOverwriteUnhandledFalseScenario.swift in Sources */ = {isa = PBXBuildFile; fileRef = 01ECBCF225A7522000FC0678 /* OnErrorOverwriteUnhandledFalseScenario.swift */; };
01ECBCF525A7522000FC0678 /* OnErrorOverwriteUnhandledTrueScenario.swift in Sources */ = {isa = PBXBuildFile; fileRef = 01ECBCF325A7522000FC0678 /* OnErrorOverwriteUnhandledTrueScenario.swift */; };
01F47CC4254B1B3100B184AD /* OriginalErrorNSExceptionScenario.swift in Sources */ = {isa = PBXBuildFile; fileRef = 01F47C21254B1B2C00B184AD /* OriginalErrorNSExceptionScenario.swift */; };
Expand Down Expand Up @@ -166,6 +167,7 @@
017FBFB7254B09C300809042 /* MainWindowController.xib */ = {isa = PBXFileReference; lastKnownFileType = file.xib; path = MainWindowController.xib; sourceTree = "<group>"; };
01AF6A4F258A00DE00FFC803 /* BareboneTestScenarios.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = BareboneTestScenarios.swift; sourceTree = "<group>"; };
01AF6A83258BB38A00FFC803 /* DispatchCrashScenario.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = DispatchCrashScenario.swift; sourceTree = "<group>"; };
01E0DB0425E8E90500A740ED /* AppDurationScenario.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = AppDurationScenario.swift; sourceTree = "<group>"; };
01ECBCF225A7522000FC0678 /* OnErrorOverwriteUnhandledFalseScenario.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = OnErrorOverwriteUnhandledFalseScenario.swift; sourceTree = "<group>"; };
01ECBCF325A7522000FC0678 /* OnErrorOverwriteUnhandledTrueScenario.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = OnErrorOverwriteUnhandledTrueScenario.swift; sourceTree = "<group>"; };
01F47C21254B1B2C00B184AD /* OriginalErrorNSExceptionScenario.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = OriginalErrorNSExceptionScenario.swift; sourceTree = "<group>"; };
Expand Down Expand Up @@ -355,6 +357,7 @@
01F47C4A254B1B2D00B184AD /* AccessNonObjectScenario.h */,
01F47C5B254B1B2E00B184AD /* AccessNonObjectScenario.m */,
01F47C60254B1B2E00B184AD /* AppAndDeviceAttributesScenario.swift */,
01E0DB0425E8E90500A740ED /* AppDurationScenario.swift */,
01018BAA25E417EC000312C6 /* AsyncSafeMallocScenario.m */,
01F47C73254B1B2E00B184AD /* AsyncSafeThreadScenario.h */,
01F47C40254B1B2D00B184AD /* AsyncSafeThreadScenario.m */,
Expand Down Expand Up @@ -666,6 +669,7 @@
01F47CE2254B1B3100B184AD /* SwiftCrash.swift in Sources */,
01F47CE9254B1B3100B184AD /* SIGTRAPScenario.m in Sources */,
01F47CC8254B1B3100B184AD /* AutoSessionScenario.m in Sources */,
01E0DB0625E8E95700A740ED /* AppDurationScenario.swift in Sources */,
01F47D2D254B1B3100B184AD /* OnErrorOverwriteScenario.swift in Sources */,
01F47CC7254B1B3100B184AD /* MetadataRedactionDefaultScenario.swift in Sources */,
01F47CEC254B1B3100B184AD /* SessionCallbackCrashScenario.swift in Sources */,
Expand Down
37 changes: 37 additions & 0 deletions features/fixtures/shared/scenarios/AppDurationScenario.swift
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,37 @@
//
// AppDurationScenario.swift
// macOSTestApp
//
// Created by Nick Dowell on 26/02/2021.
// Copyright © 2021 Bugsnag Inc. All rights reserved.
//

import Bugsnag

class AppDurationScenario: Scenario {

var startDate: Date!
var startTime: DispatchTime!

override func startBugsnag() {
config.autoTrackSessions = false
config.sendThreads = .never
startDate = Date()
startTime = .now()
super.startBugsnag()
}

override func run() {
DispatchQueue(label: "AppDurationScenario").async {
// If the events are too close together, they will not be sent in the correct order.
// This is because -[BugsnagFileStore allFilesByName] returns files in a random order.
// The 1 second delay in -[BugsnagApiClient flushPendingData] means the spacing needs
// to be quite large in order to get correct ordering of events.
for delay in [0.0, 2.7, 5.5] {
// DispatchQueue.asyncAfter was found to be too inaccurate for this scenario
Thread.sleep(until: self.startDate.addingTimeInterval(delay))
Bugsnag.notifyError(NSError(domain: "AppDurationScenario", code: Int(delay * 1000.0)))
}
}
}
}
6 changes: 6 additions & 0 deletions features/steps/ios_steps.rb
View file
Original file line number Diff line number Diff line change
Expand Up @@ -148,6 +148,12 @@ def request_fields_are_equal(key, index_a, index_b)
assert_true(delta.abs < threshold_secs, "Expected current timestamp, but received #{value}")
end

Then('the event {string} is between {int} and {int}') do |field, lower, upper|
value = Maze::Helper.read_key_path(Maze::Server.errors.current[:body], "events.0.#{field}")
assert_not_nil(value, 'Expected a value')
assert_true(lower <= value && value <= upper, "Expected a value between #{lower} and #{upper}, but received #{value}")
end

Then('the event breadcrumbs contain {string} with type {string}') do |string, type|
crumbs = Maze::Helper.read_key_path(find_request(0)[:body], 'events.0.breadcrumbs')
assert_not_equal(0, crumbs.length, 'There are no breadcrumbs on this event')
Expand Down

0 comments on commit c00cd12

Please sign in to comment.