Unable to upload samples on Android 9.0 (Huawei P20 Pro)

[lagerspetz]

Possibly relevant adb log:

05-12 17:55:12.500  4003  4765 E SQLiteLog: (1) 
05-12 17:55:12.501  2103  2103 W NotificationViewHierarchyManager: updateNotificationShade activeNotificationSize=4;hasFaceDT: false; Detected:false
05-12 17:55:12.502  2103  3111 I NotificationInflation5: doInBackground is end
05-12 17:55:12.504  2103  2202 D ReporterUtil:  e id:344 type:{pkg:com.android.settings,hw_type:null,hw_btw:false,onGoing:true,importance:1}
05-12 17:55:12.516  2103  2103 W HwKeyguardDragHelper: AnimationBlocked 
05-12 17:55:12.517  2103  2103 I NotificationInflation2: finish: entry=134106867
05-12 17:55:12.518  2103  2103 I NotificationInflation3: start: entry=134106867
05-12 17:55:12.534 22180 22190 W android.vendin: Suspending all threads took: 225.761ms
05-12 17:55:12.534  2103  2103 W HwKeyguardDragHelper: AnimationBlocked 
05-12 17:55:12.538  2103  2103 I NotificationInflation3: finish: entry=134106867
05-12 17:55:12.541 22114 22146 E SampleDB: in writeString in org.apache.thrift.protocol.TCompactProtocol(363)
05-12 17:55:12.541 22114 22146 E SampleDB: 	in write in edu.berkeley.cs.amplab.carat.thrift.Sample$SampleStandardScheme(3403)
05-12 17:55:12.541 22114 22146 E SampleDB: 	in write in edu.berkeley.cs.amplab.carat.thrift.Sample$SampleStandardScheme(2842)
05-12 17:55:12.541 22114 22146 E SampleDB: 	in write in edu.berkeley.cs.amplab.carat.thrift.Sample(2523)
05-12 17:55:12.541 22114 22146 E SampleDB: 	in serialize in org.apache.thrift.TSerializer(79)
05-12 17:55:12.541 22114 22146 E SampleDB: 	in addSample in edu.berkeley.cs.amplab.carat.android.storage.SampleDB(438)
05-12 17:55:12.541 22114 22146 E SampleDB: 	in putSample in edu.berkeley.cs.amplab.carat.android.storage.SampleDB(410)
05-12 17:55:12.541 22114 22146 E SampleDB: 	in sample in edu.berkeley.cs.amplab.carat.android.sampling.Sampler(61)
05-12 17:55:12.541 22114 22146 E SampleDB: 	in onHandleIntent in edu.berkeley.cs.amplab.carat.android.receivers.IntentRouter(108)
05-12 17:55:12.541 22114 22146 E SampleDB: 	in handleMessage in android.app.IntentService$ServiceHandler(76)
05-12 17:55:12.541 22114 22146 E SampleDB: 	in dispatchMessage in android.os.Handler(109)
05-12 17:55:12.541 22114 22146 E SampleDB: 	in loop in android.os.Looper(207)
05-12 17:55:12.541 22114 22146 E SampleDB: 	in run in android.os.HandlerThread(65)

[lagerspetz]

Underlying issue: Unable to store samples:

2019-05-12 20:16:01.613 28616-28670/edu.berkeley.cs.amplab.carat.android E/SampleDB: Unable to serialize or put serialized sample to DB!: null
2019-05-12 20:16:01.613 28616-28670/edu.berkeley.cs.amplab.carat.android E/SampleDB: in writeString in org.apache.thrift.protocol.TCompactProtocol(363)
    	in write in edu.berkeley.cs.amplab.carat.thrift.Sample$SampleStandardScheme(3403)
    	in write in edu.berkeley.cs.amplab.carat.thrift.Sample$SampleStandardScheme(2842)
    	in write in edu.berkeley.cs.amplab.carat.thrift.Sample(2523)
    	in serialize in org.apache.thrift.TSerializer(79)
    	in addSample in edu.berkeley.cs.amplab.carat.android.storage.SampleDB(438)
    	in putSample in edu.berkeley.cs.amplab.carat.android.storage.SampleDB(410)
    	in sample in edu.berkeley.cs.amplab.carat.android.sampling.Sampler(61)
    	in onHandleIntent in edu.berkeley.cs.amplab.carat.android.receivers.IntentRouter(90)
    	in handleMessage in android.app.IntentService$ServiceHandler(76)
    	in dispatchMessage in android.os.Handler(109)
    	in loop in android.os.Looper(207)
    	in run in android.os.HandlerThread(65)
2019-05-12 20:16:01.619 28616-28670/edu.berkeley.cs.amplab.carat.android E/Sampler: Failed to store sample for android.intent.action.BATTERY_CHANGED:
    Sample(uuId:d324456ecf002b17, timestamp:1.557681361294E9, piList:[ProcessInfo(pId:-1, pName:com.android.providers.blockednumber, importance:Foreground app, installationPkg:null, processes:[PackageProcess(processName:com.android.providers.blockednumber, processCount:-1, uId:-1, sleeping:false, foreground:false, foregroundTime:0.0, launchCount:1.0, importance:100, crashCount:-1, lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0)], ignoringBatteryOptimizations:false), ProcessInfo(pId:-1, pName:com.huawei.vassistant, applicationLabel:HiVoice, isSystemApp:true, importance:Foreground app, versionName:18.1.2.308, versionCode:1812308, installationPkg:null, processes:[PackageProcess(processName:com.huawei.vassistant, processCount:-1, uId:-1, sleeping:false, foreground:false, foregroundTime:0.0, launchCount:1.0, importance:100, crashCount:-1, lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0)], ignoringBatteryOptimizations:false), ProcessInfo(pId:-1, pName:com.huawei.android.launcher, applicationLabel:Huawei Home, isSystemApp:true, importance:Foreground app, versionName:9.0.3.332, versionCode:903332, installationPkg:null, processes:[PackageProcess(processName:com.huawei.android.launcher, processCount:-1, uId:-1, sleeping:false, foreground:false, foregroundTime:7692.0, launchCount:2.0, importance:100, crashCount:-1, lastStartSinceBoot:-1.0, lastStartTimestamp:1.557681357136E12)], ignoringBatteryOptimizations:false), ProcessInfo(pId:-1, pName:android, importance:Foreground app, installationPkg:null, processes:[PackageProcess(processName:android, processCount:-1, uId:-1, sleeping:false, foreground:false, foregroundTime:0.0, launchCount:1.0, importance:100, crashCount:-1, lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0)], ignoringBatteryOptimizations:true), ProcessInfo(pId:-1, pName:edu.berkeley.cs.amplab.carat.android, applicationLabel:Carat, isSystemApp:false, importance:Foreground app, versionName:2.2.1, versionCode:140, installationPkg:null, processes:[PackageProcess(processName:edu.berkeley.cs.amplab.carat.android@service, processCount:1, uId:10230, sleeping:false, foreground:false, foregroundTime:-1.0, launchCount:-1.0, importance:300, crashCount:0, lastStartSinceBoot:5.92678631E8, lastStartTimestamp:-1.0), PackageProcess(processName:edu.berkeley.cs.amplab.carat.android:location, processCount:1, uId:-1, sleeping:false, foreground:false, foregroundTime:-1.0, launchCount:-1.0, importance:400, crashCount:-1, lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0), PackageProcess(processName:edu.berkeley.cs.amplab.carat.android, processCount:1, uId:-1, sleeping:false, foreground:false, foregroundTime:18794.0, launchCount:1.0, importance:100, crashCount:-1, lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0)], ignoringBatteryOptimizations:false), ProcessInfo(pId:-1, pName:com.android.providers.userdictionary, importance:Foreground app, installationPkg:null, processes:[PackageProcess(processName:com.android.providers.userdictionary, processCount:-1, uId:-1, sleeping:false, foreground:false, foregroundTime:0.0, launchCount:1.0, importance:100, crashCount:-1, lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0)], ignoringBatteryOptimizations:false)], batteryState:Charging, batteryLevel:0.77, memoryActive:18432, memoryInactive:1681916, memoryFree:5838192, memoryUser:178808, triggeredBy:android.intent.action.BATTERY_CHANGED, networkStatus:WIFI, distanceTraveled:0.0, screenBrightness:-1, networkDetails:NetworkDetails(networkType:WIFI, mobileNetworkType:lte, mobileDataStatus:disconnected, mobileDataActivity:none, roamingEnabled:false, wifiStatus:enabled, wifiSignalStrength:-37, wifiLinkSpeed:780, wifiApStatus:disabled, networkOperator:Saunalahti;elisa, simOperator:elisa, mcc:244, mnc:05, mobileSignalStrength:-110), batteryDetails:BatteryDetails(batteryCharger:usb, batteryHealth:Good, batteryVoltage:4.048, batteryTemperature:29.0, batteryTechnology:Li-poly, batteryCapacity:4000.0), cpuStatus:CpuStatus(cpuUsage:0.4394693076610565, uptime:592678.0, slee

[lagerspetz]

Seems to be caused the Thrift serializer failing to serialize the sample for some reason. Also Thrift's SimpleJson serializer fails on it. Perhaps something has changed in the Android platform so that Thrift's dependencies are no longer available?

[jhamberg]

First things that come to mind: some weird bytes that are not UTF8? Or an interrupted write that leads to a null or corrupted sample? (This seems to happen quite often with aggressive background task limitations) https://github.com/apache/thrift/blob/master/lib/java/src/org/apache/thrift/protocol/TCompactProtocol.java#L363

[jhamberg]

Is this for all samples or this specific one?

[lagerspetz]

All samples. I deleted the app, reinstalled from current master to get access to current logcat. New samples fail to store on my device. At least first 4000 characters of Sample content are fine (logcat limitation).

[jhamberg]

Weird, we might want to look into Apache Avro next (JSON based, but no server/client-gen) if we plan on moving away from Thrift. One more thing that comes to mind is that perhaps down the line Thrift is allocating a buffer of insufficient size and our samples have simply started exceeding that.

[lagerspetz]

2019-05-12 21:38:39.258 1736-1888/edu.berkeley.cs.amplab.carat.android
D/SampleDB: SampleDB.putSample(). About to save a sample to the DB. 
uuid=d324456ecf002b17, timestamp=1.557686318975E9, 
timezone=Europe/Helsinki, batteryLevel=0.84, batteryState=Charging, 
developerMode=1, distanceTraveled=0.0, memoryActive=20780, 
memoryFree=5838192, memoryInactive=1783260, memoryWired=0, 
screenBrightness=-1, networkStatus=WIFI, screenOn=1, unknownSources=1, 
batteryCapacity=4000.0, batteryCharger=usb, batteryHealth=Good, 
batteryTechnology=Li-poly, batteryVoltage=4.134, 
cpuStatus=CpuStatus(cpuUsage:0.7134328484535217, uptime:597636.0, sleeptime:488615.0, 
currentFrequencies:[1690000, 1690000, 1690000, 1690000, 1652000, 1652000, 1652000, 1652000], 
minFrequencies:[509000, 509000, 509000, 509000, 682000, 682000, 682000, 682000], 
maxFrequencies:[1844000, 1844000, 1844000, 1844000, 2362000, 2362000, 2362000, 2362000]), 
mobileDataActivity=none, mobileDataStatus=disconnected, mobileNetworkType=lte, 
networkType=WIFI, wifiLinkSpeed=866, wifiSignalStrength=-45, wifiStatus=enabled, 
simOperator=elisa, networkOperator=Saunalahti;elisa, PiListSize=20

looks normal, but error:

2019-05-12 21:38:28.746 1736-1867/edu.berkeley.cs.amplab.carat.android E/SampleDB: Unable to serialize or put serialized sample to DB!: null
2019-05-12 21:38:28.746 1736-1867/edu.berkeley.cs.amplab.carat.android E/SampleDB: in writeString in org.apache.thrift.protocol.TCompactProtocol(363)
    	in write in edu.berkeley.cs.amplab.carat.thrift.Sample$SampleStandardScheme(3403)
    	in write in edu.berkeley.cs.amplab.carat.thrift.Sample$SampleStandardScheme(2842)
    	in write in edu.berkeley.cs.amplab.carat.thrift.Sample(2523)
    	in serialize in org.apache.thrift.TSerializer(79)
    	in addSample in edu.berkeley.cs.amplab.carat.android.storage.SampleDB(438)
    	in putSample in edu.berkeley.cs.amplab.carat.android.storage.SampleDB(410)
    	in sample in edu.berkeley.cs.amplab.carat.android.sampling.Sampler(61)
    	in onHandleIntent in edu.berkeley.cs.amplab.carat.android.receivers.IntentRouter(90)
    	in handleMessage in android.app.IntentService$ServiceHandler(76)
    	in dispatchMessage in android.os.Handler(109)
    	in loop in android.os.Looper(207)
    	in run in android.os.HandlerThread(65)
2019-05-12 21:38:28.753 1736-1867/edu.berkeley.cs.amplab.carat.android E/Sampler: Failed to store sample for android.intent.action.BATTERY_CHANGED:
    Sample(uuId:d324456ecf002b17, timestamp:1.557686308428E9, piList:[ProcessInfo(pId:-1, 
pName:com.whatsapp, applicationLabel:WhatsApp, isSystemApp:false, importance:Foreground app, 
versionName:2.19.115, versionCode:452767, installationPkg:com.android.vending, processes:
[PackageProcess(processName:com.whatsapp, processCount:-1, uId:-1, sleeping:false, 
foreground:false, foregroundTime:0.0, launchCount:1.0, importance:100, crashCount:-1, 
lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0)], ignoringBatteryOptimizations:false), 
ProcessInfo(pId:-1, pName:com.huawei.search, applicationLabel:HiSearch, isSystemApp:true, 
importance:Foreground app, versionName:9.0.2.303_OVE, versionCode:90002303, 
installationPkg:null, processes:[PackageProcess(processName:com.huawei.search, processCount:-1, 
uId:-1, sleeping:false, foreground:false, foregroundTime:0.0, launchCount:1.0, importance:100, 
crashCount:-1, lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0)], ignoringBatteryOptimizations:false), 
ProcessInfo(pId:-1, pName:android, importance:Foreground app, installationPkg:null, processes:
[PackageProcess(processName:android, processCount:-1, uId:-1, sleeping:false, foreground:false, 
foregroundTime:0.0, launchCount:1.0, importance:100, crashCount:-1, lastStartSinceBoot:-1.0, 
lastStartTimestamp:-1.0)], ignoringBatteryOptimizations:true), ProcessInfo(pId:-1, 
pName:com.touchtype.swiftkey, applicationLabel:SwiftKey Keyboard, isSystemApp:true, 
importance:Foreground app, versionName:7.2.8.25, versionCode:944243088, installationPkg:null, 
processes:[PackageProcess(processName:com.touchtype.swiftkey, processCount:-1, uId:-1, 
sleeping:false, foreground:false, foregroundTime:0.0, launchCount:1.0, importance:100, 
crashCount:-1, lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0)], ignoringBatteryOptimizations:false), 
ProcessInfo(pId:-1, pName:com.android.defcontainer, applicationLabel:Package Access Helper, 
isSystemApp:true, importance:Foreground app, versionName:9, versionCode:28, installationPkg:null, 
processes:[PackageProcess(processName:com.android.defcontainer, processCount:-1, uId:-1, 
sleeping:false, foreground:false, foregroundTime:0.0, launchCount:1.0, importance:100, 
crashCount:-1, lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0)], ignoringBatteryOptimizations:false),
 ProcessInfo(pId:-1, pName:com.tencent.mm, applicationLabel:WeChat, isSystemApp:false, 
importance:Foreground app, versionName:7.0.3, versionCode:1381, 
installationPkg:com.android.vending, processes:[PackageProcess(processName:com.tencent.mm,
 processCount:-1, uId:-1, sleeping:false, foreground:false, foregroundTime:0.0, launchCount:1.0, 
importance:100, crashCount:-1, lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0)], 
ignoringBatteryOptimizations:true), ProcessInfo(pId:-1, pName:com.android.carrierconfig, 
applicationLabel:com.android.carrierconfig, isSystemApp:true, importance:Foreground app, 
versionName:1.0.0, versionCode:1, installationPkg:null, processes:
[PackageProcess(processName:com.android.carrierconfig, processCount:-1, uId:-1, sleeping:false, 
foreground:false, foregroundTime:0.0, launchCount:1.0, importance:100, crashCount:-1, 
lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0)], ignoringBatteryOptimizations:false), 
ProcessInfo(pId:-1, pName:com.huawei.hwid, applicationLabel:Huawei Mobile Services, 
isSystemApp:true, importance:Foreground app, versionName:2.6.5.306, versionCode:20605306, 
installationPkg:null, processes:[PackageProcess(processName:com.huawei.hwid, processCount:-1, 
uId:-1, sleeping:false, foreground:false, foregroundTime:0.0, launchCount:1.0, importance:100, 
crashCount:-1, lastStartSinceBoot:-1.0, lastStartTimestamp:-1.0)], ignoringBatteryOptimizations:false), 
ProcessInfo(pId:-1, pName:com.android.chrome, applicationLabel:Chrome, isSystemApp:true, 
importance:Foreground app, versionName:73.0.3683.90, versionCode:368309052, 
installationPkg:null, processes:[PackageProcess(processName:com.android.chrome, 
processCount:-1, uId:-1, sleeping:false, foreground:false, foregro...)
2019-05-12 21:38:28.762 1736-1867/edu.berkeley.cs.amplab.carat.android D/IntentRouter: Next sampling scheduled in 899 seconds

[jhamberg]

Do you get the following line in your logcat with DEBUG enabled?

Logger.d("SampleDB.addSample()", "The sample's battery level=" + s.getBatteryLevel());

I'm wondering whether the sample turns null before it reaches serializer.serialize(s).

(https://github.com/carat-project/carat-android/blob/master/caratApp/src/main/java/edu/berkeley/cs/amplab/carat/android/storage/SampleDB.java#L411)

[lagerspetz]

It doesn't; I have been printing it from just before the serialize call and toString() was fine.
Full sample: https://pastebin.com/CfvtFEJN
Looks like installationPkg are null on some apps, but that should be normal. Also this happens: thermalZoneNames:[null, null, ...

[jhamberg]

I was under the impression that Thrift accepted those, but might be worth checking. Otherwise the sample looks perfectly normal.

[jhamberg]

It would make sense that it was caused by null values in an array which we probably have not had before. Thermal zones were among the last things that have been added.

[lagerspetz]

Setting thermal zones parameter to null causes the error not to show.
This hack fixes sample storage, but drops thermal zone names: 418712a
TODO: Proper way to call those "unnamed" or whatever we decide.

[lagerspetz]

The modified version has enabled my Huawei P20 Pro device to get an active battery life estimate J-Score for the first time. Permission dialogs must be fixed until the version can go public though. Here's the version for testing: https://github.com/carat-project/carat-android/releases/tag/v2.21.0-alpha