Closed LouisLuo2016 closed 7 years ago
Hi, the "Characteristic write error: 3" you get is "Write Not Permitted", so it has to be some caching issue.
Could you, please, in your DfuService class override isDebug() method and make it return true or: BuildConfig.DEBUG
?
@Override
protected boolean isDebug() {
return BuildConfig.DEBUG;
}
You will get more logs there. Then paste the new logcat output here. I'm mostly concern about a text: Refreshing result: true/false or En exception occurred while refreshing device that is generated by this method.
Other questions:
Thanks!
Yes. I am using legacy DFU from SDK9. nRF51822 is used in our device side. And some Chinese brand Android phones are used for the test. We use buttonless jump. And we change MAC address in bootloader mode. No bonding is used in our device.
11-25 20:07:37.813 12621-12621/com.putao.wd E/BluetoothFuncManager: onProgressChanged info:C7:6B:39:0C:26:9A percent98
11-25 20:07:38.553 12621-12621/com.putao.wd E/BluetoothFuncManager: onProgressChanged info:C7:6B:39:0C:26:9A percent99
11-25 20:07:39.483 12621-12621/com.putao.wd E/BluetoothFuncManager: onProgressChanged info:C7:6B:39:0C:26:9A percent100
11-25 20:07:39.493 1289-1289/? E/wpa_supplicant: wpa_driver_nl80211_driver_cmd: failed to issue private commands
11-25 20:07:39.493 945-1095/? E/WifiStateMachine: Unexpected BatchedScanResults :null
11-25 20:07:39.493 1289-1289/? E/wpa_supplicant: wpa_driver_nl80211_driver_cmd: failed to issue private commands
11-25 20:07:39.503 14796-14796/? I/Log_level_control: YWW4
11-25 20:07:39.853 12621-12621/com.putao.wd E/BluetoothFuncManager: onDeviceDisconnecting info:C7:6B:39:0C:26:9A
11-25 20:07:39.963 945-945/? W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.sendStickyBroadcast:1351 android.net.wifi.WifiStatusBar.updateWifi:240 android.net.wifi.WifiStatusBar$1.onReceive:85 android.app.LoadedApk$ReceiverDispatcher$Args.run:764 android.os.Handler.handleCallback:733
11-25 20:07:39.983 945-945/? W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.sendStickyBroadcast:1351 android.net.wifi.WifiStatusBar.updateWifi:240 android.net.wifi.WifiStatusBar$1.onReceive:85 android.app.LoadedApk$ReceiverDispatcher$Args.run:764 android.os.Handler.handleCallback:733
11-25 20:07:40.053 2055-2242/? E/bt-btm: btm_sec_disconnected - Clearing Pending flag
11-25 20:07:40.053 2055-2242/? W/bt-l2cap: L2CA_SetDesireRole() new:x0, disallow_switch:0
11-25 20:07:40.053 2055-2242/? W/bt-btif: bta_dm_act no entry for connected service cbs
11-25 20:07:40.053 2055-2242/? W/bt-l2cap: L2CA_SetDesireRole() new:x0, disallow_switch:0
11-25 20:07:40.053 2055-2242/? W/bt-btif: bta_dm_act no entry for connected service cbs
11-25 20:07:40.053 2055-2242/? W/bt-l2cap: L2CA_SetDesireRole() new:x0, disallow_switch:0
11-25 20:07:40.143 12621-12634/com.putao.wd E/BluetoothFuncManager: onConnectionStateChange()status:0 newState:0
11-25 20:07:40.153 8651-8651/? W/LoadedApk: perform long-running operations in onReceive, ordered=false ~duration=126ms: cgg@426531b8 Intent { act=android.net.wifi.STATE_CHANGE flg=0x4000010 (has extras) }
11-25 20:07:40.153 945-945/? W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.sendStickyBroadcast:1351 android.net.wifi.WifiStatusBar.updateWifi:240 android.net.wifi.WifiStatusBar$1.onReceive:85 android.app.LoadedApk$ReceiverDispatcher$Args.run:764 android.os.Handler.handleCallback:733
11-25 20:07:40.173 12621-12621/com.putao.wd E/BluetoothFuncManager: onDfuCompleted info:C7:6B:39:0C:26:9A
11-25 20:07:40.173 945-1105/? E/ConnectivityService: Unexpected mtu value: android.net.wifi.WifiStateTracker@42e70608
11-25 20:07:40.233 14826-14826/? E/SoftapReceiver: length is5get last ssid isPutao
11-25 20:07:40.853 8651-8651/? W/System.err: java.lang.IllegalArgumentException: Base64-encoded string must have at least four characters, but length specified was 2
11-25 20:07:40.853 8651-8651/? W/System.err: at com.qihoo.freewifi.plugin.utils.Base64.decode(freewifi:358)
11-25 20:07:40.853 8651-8651/? W/System.err: at com.qihoo.freewifi.plugin.utils.Base64.decode(freewifi:415)
11-25 20:07:40.853 8651-8651/? W/System.err: at com.qihoo.freewifi.plugin.utils.Base64.decode(freewifi:399)
11-25 20:07:40.853 8651-8651/? W/System.err: at freewifi.fg.b(freewifi:79)
11-25 20:07:40.853 8651-8651/? W/System.err: at freewifi.co.onSuccess(freewifi:132)
11-25 20:07:40.853 8651-8651/? W/System.err: at com.qihoo.freewifi.plugin.network.AsyncRequest.a(freewifi:363)
11-25 20:07:40.853 8651-8651/? W/System.err: at freewifi.db.onSuccess(freewifi:185)
11-25 20:07:40.853 8651-8651/? W/System.err: at freewifi.de.run(freewifi:215)
11-25 20:07:40.853 8651-8651/? W/System.err: at android.os.Handler.handleCallback(Handler.java:733)
11-25 20:07:40.853 8651-8651/? W/System.err: at android.os.Handler.dispatchMessage(Handler.java:95)
11-25 20:07:40.853 8651-8651/? W/System.err: at android.os.Looper.loop(Looper.java:136)
11-25 20:07:40.853 8651-8651/? W/System.err: at android.app.ActivityThread.main(ActivityThread.java:5217)
11-25 20:07:40.853 8651-8651/? W/System.err: at java.lang.reflect.Method.invokeNative(Native Method)
11-25 20:07:40.853 8651-8651/? W/System.err: at java.lang.reflect.Method.invoke(Method.java:515)
11-25 20:07:40.853 8651-8651/? W/System.err: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:818)
11-25 20:07:40.853 8651-8651/? W/System.err: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:634)
11-25 20:07:40.853 8651-8651/? W/System.err: at dalvik.system.NativeStart.main(Native Method)
11-25 20:07:41.213 945-2521/? W/XTWiFiOS: No entry in secure settings for enhanced location services: false
11-25 20:07:41.253 1717-1717/? W/a: getContentProvider,fake fail 2=3416a75f4cea9109507cacd8e2f2aefc
11-25 20:07:41.283 1985-1985/? W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:1549 android.content.ContextWrapper.startService:494 android.content.ContextWrapper.startService:494 com.xmpp.android.service.BootstrapReceiver.onReceive:50 android.app.ActivityThread.handleReceiver:2432
11-25 20:07:41.673 14903-14903/? W/HanziToPinyin: There is no Chinese collator, HanziToPinyin is disabled
11-25 20:07:41.673 14903-14903/? E/SQLiteDatabase: Error inserting shelfhide=false readoffsetx=0.0 downstatus=0 publishdate=null readlasttime=0 type=9 shelfweight=0 author= bookid=10036314 newchapcount=0 coverpath=/storage/emulated/0/iReader/cover/《洗脑术》.jpg isbn=null name=洗脑术 path=/storage/emulated/0/iReader/books/《洗脑术》.ebk3 coverusedef=false downurl=null readsummary=null readoffsety=0.0 pinyin=XNS tags=null readposition=null downtotalsize=0 bookstatus=0 class=null charset=UTF-16LE pubisher=null ext_txt3= readpercent=0.0 shelfcandel=false readzoom=0 autoorder=0 readtotaltime=null
android.database.sqlite.SQLiteConstraintException: column path is not unique (code 19)
at android.database.sqlite.SQLiteConnection.nativeExecuteForLastInsertedRowId(Native Method)
at android.database.sqlite.SQLiteConnection.executeForLastInsertedRowId(SQLiteConnection.java:865)
at android.database.sqlite.SQLiteSession.executeForLastInsertedRowId(SQLiteSession.java:788)
at android.database.sqlite.SQLiteStatement.executeInsert(SQLiteStatement.java:86)
at android.database.sqlite.SQLiteDatabase.insertWithOnConflict(SQLiteDatabase.java:1469)
at android.database.sqlite.SQLiteDatabase.insert(SQLiteDatabase.java:1339)
at com.zhangyue.iReader.b.a.a(Unknown Source)
at com.zhangyue.iReader.bookshelf.b.j.d(Unknown Source)
at com.zhangyue.iReader.app.APP.j(Unknown Source)
at com.zhangyue.iReader.app.IreaderApplication.onCreate(Unknown Source)
at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1008)
at android.app.ActivityThread.handleBindApplication(ActivityThread.java:4508)
at android.app.ActivityThread.access$1500(ActivityThread.java:142)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1273)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5217)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:515)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:818)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:634)
at dalvik.system.NativeStart.main(Native Method)
11-25 20:07:41.683 14903-14903/? W/System.err: java.io.FileNotFoundException: hyaam.ebk3
11-25 20:07:41.683 14903-14903/? W/System.err: at android.content.res.AssetManager.openAsset(Native Method)
11-25 20:07:41.683 14903-14903/? W/System.err: at android.content.res.AssetManager.open(AssetManager.java:316)
11-25 20:07:41.683 14903-14903/? W/System.err: at android.content.res.AssetManager.open(AssetManager.java:290)
11-25 20:07:41.683 14903-14903/? W/System.err: at com.zhangyue.iReader.bookshelf.b.j.d(Unknown Source)
11-25 20:07:41.683 14903-14903/? W/System.err: at com.zhangyue.iReader.app.APP.j(Unknown Source)
11-25 20:07:41.683 14903-14903/? W/System.err: at com.zhangyue.iReader.app.IreaderApplication.onCreate(Unknown Source)
11-25 20:07:41.683 14903-14903/? W/System.err: at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1008)
11-25 20:07:41.683 14903-14903/? W/System.err: at android.app.ActivityThread.handleBindApplication(ActivityThread.java:4508)
11-25 20:07:41.683 14903-14903/? W/System.err: at android.app.ActivityThread.access$1500(ActivityThread.java:142)
11-25 20:07:41.683 14903-14903/? W/System.err: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1273)
11-25 20:07:41.683 14903-14903/? W/System.err: at android.os.Handler.dispatchMessage(Handler.java:102)
11-25 20:07:41.683 14903-14903/? W/System.err: at android.os.Looper.loop(Looper.java:136)
11-25 20:07:41.683 14903-14903/? W/System.err: at android.app.ActivityThread.main(ActivityThread.java:5217)
11-25 20:07:41.683 14903-14903/? W/System.err: at java.lang.reflect.Method.invokeNative(Native Method)
11-25 20:07:41.683 14903-14903/? W/System.err: at java.lang.reflect.Method.invoke(Method.java:515)
11-25 20:07:41.683 14903-14903/? W/System.err: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:818)
11-25 20:07:41.683 14903-14903/? W/System.err: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:634)
11-25 20:07:41.683 14903-14903/? W/System.err: at dalvik.system.NativeStart.main(Native Method)
11-25 20:07:41.713 945-945/? E/WifiStatusBar: totalRxRate=12209,totalTxRate=2810
11-25 20:07:41.713 945-945/? W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.sendStickyBroadcast:1351 android.net.wifi.WifiStatusBar.updateWifi:240 android.net.wifi.WifiStatusBar$1.onReceive:85 android.app.LoadedApk$ReceiverDispatcher$Args.run:764 android.os.Handler.handleCallback:733
11-25 20:07:41.773 3403-3489/? W/ResponseProcessCookies: Invalid cookie header: "Set-Cookie: BAIDUID=468D87B8F3C61EEA124150477F1F4D31:FG=1; expires=Thu, 31-Dec-37 23:55:55 GMT; max-age=2145916555; path=/; domain=.baidu.com; version=1". Unable to parse expires attribute: Thu
11-25 20:07:41.853 252-376/? E/cutils: Failed to mkdirat(/storage/sdcard1/Android): Read-only file system
11-25 20:07:41.853 252-376/? W/Vold: Returning OperationFailed - no handler for errno 30
11-25 20:07:41.863 14960-14960/? W/ContextImpl: Failed to ensure directory: /storage/sdcard1/Android/data/com.yulong.android.coolmall/cache
11-25 20:07:41.863 252-376/? E/cutils: Failed to mkdirat(/storage/sdcard1/Android): Read-only file system
11-25 20:07:41.863 14960-14960/? W/ContextImpl: Failed to ensure directory: /storage/sdcard1/Android/data/com.yulong.android.coolmall/cache
11-25 20:07:41.863 14960-14960/? W/ImageLoader: memoryCache() and memoryCacheSize() calls overlap each other
11-25 20:07:41.863 14960-14960/? W/ImageLoader: discCache(), discCacheSize() and discCacheFileCount calls overlap each other
11-25 20:07:41.863 14960-14960/? W/ImageLoader: discCache(), discCacheSize() and discCacheFileCount calls overlap each other
11-25 20:07:41.863 14960-14960/? W/ImageLoader: discCache() and discCacheFileNameGenerator() calls overlap each other
11-25 20:07:41.863 252-376/? W/Vold: Returning OperationFailed - no handler for errno 30
11-25 20:07:41.903 12621-13150/com.putao.wd E/BluetoothFuncManager: disconnect()
11-25 20:07:41.903 2055-2242/? E/bt-btif: No such connection need to be cancelled
11-25 20:07:41.903 2055-2242/? E/bt-btif: Do not find the bg connection mask for the remote device
11-25 20:07:42.053 14980-14980/? E/Utility: com.baidu.android.pushservice.PushServiceReceiverdid not declaredandroid.intent.action.BOOT_COMPLETED
11-25 20:07:42.113 14948-14948/? W/HanziToPinyin: There is no Chinese collator, HanziToPinyin is disabled
11-25 20:07:42.123 14948-14948/? E/SQLiteDatabase: Error inserting shelfhide=false readoffsetx=0.0 downstatus=0 publishdate=null readlasttime=0 type=9 shelfweight=0 author= bookid=10036314 newchapcount=0 coverpath=/storage/emulated/0/iReader/cover/《洗脑术》.jpg isbn=null name=洗脑术 path=/storage/emulated/0/iReader/books/《洗脑术》.ebk3 coverusedef=false downurl=null readsummary=null readoffsety=0.0 pinyin=XNS tags=null readposition=null downtotalsize=0 bookstatus=0 class=null charset=UTF-16LE pubisher=null ext_txt3= readpercent=0.0 shelfcandel=false readzoom=0 autoorder=0 readtotaltime=null
android.database.sqlite.SQLiteConstraintException: column path is not unique (code 19)
at android.database.sqlite.SQLiteConnection.nativeExecuteForLastInsertedRowId(Native Method)
at android.database.sqlite.SQLiteConnection.executeForLastInsertedRowId(SQLiteConnection.java:865)
at android.database.sqlite.SQLiteSession.executeForLastInsertedRowId(SQLiteSession.java:788)
at android.database.sqlite.SQLiteStatement.executeInsert(SQLiteStatement.java:86)
at android.database.sqlite.SQLiteDatabase.insertWithOnConflict(SQLiteDatabase.java:1469)
at android.database.sqlite.SQLiteDatabase.insert(SQLiteDatabase.java:1339)
at com.zhangyue.iReader.b.a.a(Unknown Source)
at com.zhangyue.iReader.bookshelf.b.j.d(Unknown Source)
at com.zhangyue.iReader.app.APP.j(Unknown Source)
at com.zhangyue.iReader.app.IreaderApplication.onCreate(Unknown Source)
at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1008)
at android.app.ActivityThread.handleBindApplication(ActivityThread.java:4508)
at android.app.ActivityThread.access$1500(ActivityThread.java:142)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1273)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5217)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:515)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:818)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:634)
at dalvik.system.NativeStart.main(Native Method)
11-25 20:07:42.243 14948-14948/? W/System.err: java.io.FileNotFoundException: hyaam.ebk3
11-25 20:07:42.243 14948-14948/? W/System.err: at android.content.res.AssetManager.openAsset(Native Method)
11-25 20:07:42.243 14948-14948/? W/System.err: at android.content.res.AssetManager.open(AssetManager.java:316)
11-25 20:07:42.243 14948-14948/? W/System.err: at android.content.res.AssetManager.open(AssetManager.java:290)
11-25 20:07:42.243 14948-14948/? W/System.err: at com.zhangyue.iReader.bookshelf.b.j.d(Unknown Source)
11-25 20:07:42.243 14948-14948/? W/System.err: at com.zhangyue.iReader.app.APP.j(Unknown Source)
11-25 20:07:42.243 14948-14948/? W/System.err: at com.zhangyue.iReader.app.IreaderApplication.onCreate(Unknown Source)
11-25 20:07:42.243 14948-14948/? W/System.err: at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1008)
11-25 20:07:42.243 14948-14948/? W/System.err: at android.app.ActivityThread.handleBindApplication(ActivityThread.java:4508)
11-25 20:07:42.243 14948-14948/? W/System.err: at android.app.ActivityThread.access$1500(ActivityThread.java:142)
11-25 20:07:42.243 14948-14948/? W/System.err: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1273)
11-25 20:07:42.243 14948-14948/? W/System.err: at android.os.Handler.dispatchMessage(Handler.java:102)
11-25 20:07:42.243 14948-14948/? W/System.err: at android.os.Looper.loop(Looper.java:136)
11-25 20:07:42.243 14948-14948/? W/System.err: at android.app.ActivityThread.main(ActivityThread.java:5217)
11-25 20:07:42.243 14948-14948/? W/System.err: at java.lang.reflect.Method.invokeNative(Native Method)
11-25 20:07:42.243 14948-14948/? W/System.err: at java.lang.reflect.Method.invoke(Method.java:515)
11-25 20:07:42.243 14948-14948/? W/System.err: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:818)
11-25 20:07:42.243 14948-14948/? W/System.err: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:634)
11-25 20:07:42.243 14948-14948/? W/System.err: at dalvik.system.NativeStart.main(Native Method)
11-25 20:07:42.253 15023-15023/? W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:1549 android.content.ContextWrapper.startService:494 android.content.ContextWrapper.startService:494 com.yulong.receiver.NetChangedBroadcastReceiver.onReceive:99 android.app.ActivityThread.handleReceiver:2432
11-25 20:07:42.273 9114-9271/? E/NetworkStats: MSG_PERFORM_POLL
11-25 20:07:42.483 15041-15041/? W/FeatureConfig: Could not get this feature:is_support_double_system, value is null
java.lang.Throwable
at com.yulong.android.feature.FeatureConfig.getIntValue(FeatureConfig.java:474)
at com.yulong.android.settings.a.d.
Hi, it looks like you didn't override the isDebug() method, just copied the whole LogCat. But the important part is still not there. I'm interessted mostly in locs with tag= DfuBaseService.
11-25 20:07:37.813 12621-12621/com.putao.wd E/BluetoothFuncManager: onProgressChanged info:C7:6B:39:0C:26:9A percent98 11-25 20:07:38.553 12621-12621/com.putao.wd E/BluetoothFuncManager: onProgressChanged info:C7:6B:39:0C:26:9A percent99 11-25 20:07:39.483 12621-12621/com.putao.wd E/BluetoothFuncManager: onProgressChanged info:C7:6B:39:0C:26:9A percent100 11-25 20:07:39.853 12621-12621/com.putao.wd E/BluetoothFuncManager: onDeviceDisconnecting info:C7:6B:39:0C:26:9A 11-25 20:07:40.143 12621-12634/com.putao.wd E/BluetoothFuncManager: onConnectionStateChange()status:0 newState:0 11-25 20:07:40.173 12621-12621/com.putao.wd E/BluetoothFuncManager: onDfuCompleted info:C7:6B:39:0C:26:9A 11-25 20:07:41.903 12621-13150/com.putao.wd E/BluetoothFuncManager: disconnect() 11-25 20:08:02.033 12621-12621/com.putao.wd E/BluetoothFuncManager: disconnect() 11-25 20:08:02.123 12621-12633/com.putao.wd E/BluetoothFuncManager: onLeScan bluetoothDevice:C7:6B:39:0C:26:99 11-25 20:08:02.243 12621-12969/com.putao.wd E/BluetoothFuncManager: onConnectionStateChange()status:0 newState:2 11-25 20:08:02.263 12621-15276/com.putao.wd E/BluetoothFuncManager: onServicesDiscovered()status:0 11-25 20:08:02.903 12621-13150/com.putao.wd E/OtaUpgradeActivity: startOTA() 11-25 20:08:02.903 12621-13150/com.putao.wd W/ContextImpl: Failed to ensure directory: /storage/sdcard1/Android/data/com.putao.wd/files 11-25 20:08:02.913 12621-13150/com.putao.wd W/ContextImpl: Failed to ensure directory: /storage/sdcard1/Android/data/com.putao.wd/files 11-25 20:08:03.863 12621-12621/com.putao.wd E/BluetoothFuncManager: startOTAUpgrade() 11-25 20:08:05.903 12621-12621/com.putao.wd E/BluetoothFuncManager: onDfuProcessStarting info:C7:6B:39:0C:26:99 11-25 20:08:08.133 12621-15053/com.putao.wd E/DfuImpl: Characteristic write error: 3 11-25 20:08:08.133 12621-15557/com.putao.wd E/DfuBaseService: Unable to write Op Code 1 (error 3) 11-25 20:08:08.133 12621-12621/com.putao.wd E/BluetoothFuncManager: onDeviceDisconnecting info:C7:6B:39:0C:26:99 11-25 20:08:08.743 12621-12621/com.putao.wd E/BluetoothFuncManager: onError error:3 message:GATT WRITE NOT PERMIT 11-25 20:08:08.903 12621-12621/com.putao.wd E/BluetoothFuncManager: disconnect()
Let me explain what I meant. To use the DFU library you have to override the BaseDfuService in your project, just like nRF Toolbox does. In this service of yours you must override Class<? extends Activity> getNotificationTarget()
method, but also MAY override boolean isDebug()
method. By default this method returns false, but if you return true (or BuildConfig.DEBUG, as in one of my previous posts) the library will generate more detailed LogCat information which can be interesting to debug your issue. If you have access to the code, and I hope you do, it's very simple to add this method and recompile project. Sorry for misunderstanding :)
Regarding BuildConfig.DEBUG: make sure the BuildConfig returned is the one from your app's package, not from dfu library's package. To be sure you may return:
@Override
protected boolean isDebug() {
return com.putao.wd.BuildConfig.DEBUG;
}
I added @Override protected boolean isDebug() { return true; }
Then, if you are using the dfu library 1.0.4, it should produce much more logs that starts with: 11-25 20:08:08.133 12621-15557/com.putao.wd E/DfuBaseService: [Some super text]
(actually any version after this commit: https://github.com/NordicSemiconductor/Android-DFU-Library/commit/750ea15bf401da52de4666bc1f2369374fa9df77). But if you have the isDebug... it should work. Maybe you need to clean and rebuild project?
But it doesn't generate those DfuBaseService detailed log. Tomorrow I will change a phone test again, I hope it can genarate deailed log.
The first Dfu: 11-27 21:56:14.431 22186-22728/com.putao.wd I/DfuBaseService: Connecting to the device... 11-27 21:56:14.454 22186-22198/com.putao.wd I/DfuBaseService: Connected to GATT server 11-27 21:56:14.458 22186-22198/com.putao.wd I/DfuBaseService: Attempting to start service discovery... succeed 11-27 21:56:14.464 22186-22199/com.putao.wd I/DfuBaseService: Services discovered 11-27 21:56:15.474 22186-22728/com.putao.wd I/DfuImpl: Reading DFU version number... 11-27 21:56:15.685 22186-22728/com.putao.wd I/DfuImpl: Version number read: 0.8 11-27 21:56:15.685 22186-22728/com.putao.wd I/DfuImpl: Enabling notifications... 11-27 21:56:17.081 22186-22728/com.putao.wd I/DfuImpl: Sending Start DFU command (Op Code = 1, Upload Mode = 4) 11-27 21:56:17.472 22186-22728/com.putao.wd I/DfuImpl: Sending image size array to DFU Packet (0b, 0b, 142544b) 11-27 21:56:21.246 22186-22728/com.putao.wd I/DfuImpl: Sending the Initialize DFU Parameters START (Op Code = 2, Value = 0) 11-27 21:56:21.657 22186-22728/com.putao.wd I/DfuImpl: Sending 142544 bytes of init packet 11-27 21:56:21.657 22186-22728/com.putao.wd I/DfuImpl: Sending init packet (Value = FF-FF-FF-FF-FF-FF-00-00-01-00-64-00-84-17) 11-27 21:56:21.668 22186-22728/com.putao.wd I/DfuImpl: Sending the Initialize DFU Parameters COMPLETE (Op Code = 2, Value = 1) 11-27 21:56:22.044 22186-22728/com.putao.wd I/DfuImpl: Sending Receive Firmware Image request (Op Code = 3) 11-27 21:56:22.640 22186-22728/com.putao.wd I/DfuImpl: Uploading firmware... 11-27 22:00:58.109 22186-22728/com.putao.wd I/DfuImpl: Response received. Op Code: 16 Req Op Code = 3, Status = 1 11-27 22:00:58.112 22186-22728/com.putao.wd I/DfuImpl: Transfer of 142544 bytes has taken 267961 ms 11-27 22:00:58.113 22186-22728/com.putao.wd I/DfuImpl: Sending Validate request (Op Code = 4) 11-27 22:00:58.515 22186-22728/com.putao.wd I/DfuImpl: Response received. Op Code: 16 Req Op Code = 4, Status = 1 11-27 22:00:58.517 22186-22728/com.putao.wd I/DfuImpl: Sending Activate and Reset request (Op Code = 5) 11-27 22:01:03.111 22186-22268/com.putao.wd E/DfuBaseService: Connection state change error: 8 newState: 0 11-27 22:01:03.125 22186-22728/com.putao.wd I/DfuBaseService: Refreshing result: true 11-27 22:01:03.125 22186-22728/com.putao.wd I/DfuBaseService: Cleaning up... 11-27 22:01:03.141 22186-22186/com.putao.wd I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED The second DFU 11-27 22:01:30.380 22186-27691/com.putao.wd I/DfuBaseService: Connecting to the device... 11-27 22:01:30.406 22186-22268/com.putao.wd I/DfuBaseService: Connected to GATT server 11-27 22:01:30.417 22186-22268/com.putao.wd I/DfuBaseService: Attempting to start service discovery... succeed 11-27 22:01:30.418 22186-22268/com.putao.wd I/DfuBaseService: Services discovered 11-27 22:01:31.422 22186-27691/com.putao.wd I/DfuImpl: Reading DFU version number... 11-27 22:01:31.530 22186-27691/com.putao.wd I/DfuImpl: Version number read: 20.4 11-27 22:01:31.531 22186-27691/com.putao.wd I/DfuImpl: Enabling notifications... 11-27 22:01:32.629 22186-27691/com.putao.wd I/DfuImpl: Sending Start DFU command (Op Code = 1, Upload Mode = 4) The error: 11-27 22:01:32.687 22186-22199/com.putao.wd E/DfuImpl: Characteristic write error: 3 11-27 22:01:32.689 22186-27691/com.putao.wd E/DfuBaseService: Unable to write Op Code 1 (error 3) 11-27 22:01:32.691 22186-27691/com.putao.wd I/DfuBaseService: Disconnecting from the device... 11-27 22:01:32.692 22186-22268/com.putao.wd I/DfuBaseService: Disconnected from GATT server 11-27 22:01:32.695 22186-27691/com.putao.wd I/DfuBaseService: Refreshing result: true 11-27 22:01:32.695 22186-27691/com.putao.wd I/DfuBaseService: Cleaning up...
I have changed another phone test get the above detail log.
Thanks, that's what I wanted. Few questions:
HaHa. I am happy commit a correct log. Those questions answers:
The seond connection is not to the same MAC address.
Connect the other MAC address after the discover services.
Yes it is after my do the first dfu complete. The 30 sec delay is wait the device restart.
after the scoend DFU fail, I exit DFU activity and again DFU, it hasn't the eroor. It 's DFU success.
Yes, this is because the dfu library clears the device cache when error occurred (see "Refreshing result: true").
Ok, I know what's wrong. Let's say you have two mac addresses A and B. Looks like in your app you use address A. Then, when you switch to the first dfu, the device changes address to B so, as a new address, the cache is empty and dfu works. When it's completed the device restarts and switches address to A again (or some address C which the phone has connected before and did service discovery). The services are in the cache (and are invalid, as the device now is in dfu mode) so the phone just returns them, without doing service discovery. Mind that the value read from DFU Version char is 20.4, which means that the value returned was 0x04-14-... which doesn't seem correct, so I would say it was a coincidence that a characteristic with this handle number was readable, but it wasn't the correct dfu version char. So the error occurred even earlier and wasn't noticed.
Interesting is that it works on other phones. It doesn't look like a bug on some cheap phone model, but rather a correct Android behavior.
As a solution I would recommend either using a completely new mac address in second dfu, or: after the first dfu completes instead of starting the dfu service for the second time you could connect to the target in the app, and in onConnectionStateChange call gatt.refresh() using reflections, like it is done in DfuBaseService. Then, wait ~600 ms and start the dfu service. You don't have to call discoverServices() as it will be done in the dfu lib later on. This should work on all phones, including those on which you have problems.
Philips, Thanks your help.
As a solution I would recommend either using a completely new mac address in second dfu, The second dfu used a completely new mac address, our device not surport, it has MAC + 1 and MAC two address.
another solution call gatt.refresh(), could add the solution in the dfu lib. Because my app has too many operation in onConnectionStateChange, it will make conflict.
Before you start the second DFU you may connect to the new address with a new, simple BluetoothGattCallback, that only does refresh() and starts DFU Service. It doesn't have to be one you are using now, a specially because this device is now in dfu mode so your callback is not compatible. I would add something like:
BluetoothGattCallback tmpCallback = new BluetoothGattCallback() {
@Override
onConnectionStateChange(BluetoothGatt gatt, int status, int newState) {
if (status == BluetoothGatt.GATT_SUCCESS && newState = BluetoothGatt.STATE_CONNECTED) {
refreshDeviceCache(gatt);
new Handler().postDelayed(new Runnable() {
public void run() {
gatt.disconnect(); // optional
startDfu();
}
}, 600);
}
}
};
secondTargetDevice.connectGatt(mContext, false, tmpCallback);
I don't want to add clearing cache before each connection in the library. Clearing it is a hack and should actually never be done, except on some early versions of DFU that didn't handle this correctly. For example it can't be done on iOS, so if you want your app to be updatable from iOS as well it's not an option. Btw, remember to add Service Change characteristic to you app, otherwise it's not updatable on iOS.
And there is still a question: Why you have this problem only with some devices? If it's a completely new address, one that the device had never connected before, the cache should be empty. Could you try debugging it with nRF Connect as I wrote earlier?
I also very difficult to understand this problem. It happned on those cheap phone model. Our device has two address on different conditions, one is MAC on normal state, another is MAC + 1 on DFU fail state.The first DFU MAC+1, after the first success do seconde DFU MAC. So connect two different address in DFU progress. I used nRF connect test, it also toast > DfuImpl: Characteristic write error: 3
But thers is a good news. I add refresh() on the sconed DFU, it's success. I'm very happy. Thanks very much,Philips!
Great to hear that! In nRF Connect, when you get this error 3, you may do menu->Refresh services and check what services were cached on this address.
Hi,
My application is a little bit different with others. We do two DFU process at the same time since our big app size. Normally our first DFU process would succeed. But the second one would fail. This issue would only be present in some special Android phones. Most Android phones work. But even for the same failed Android phone, it would succeed sometimes. The following log was reported by Android system. Please advise.
by the way we are using SDK9 with S110 softdevice. And single bank is used for bootloader.
11-25 18:02:11.525 19306-19306/com.putao.wd E/BluetoothFuncManager: onProgressChanged info:C7:6B:39:0C:26:9A percent98 11-25 18:02:12.285 19306-19306/com.putao.wd E/BluetoothFuncManager: onProgressChanged info:C7:6B:39:0C:26:9A percent99 11-25 18:02:13.165 19306-19306/com.putao.wd E/BluetoothFuncManager: onProgressChanged info:C7:6B:39:0C:26:9A percent100 11-25 18:02:13.525 19306-19306/com.putao.wd E/BluetoothFuncManager: onDeviceDisconnecting info:C7:6B:39:0C:26:9A 11-25 18:02:13.725 19306-19317/com.putao.wd E/BluetoothFuncManager: onConnectionStateChange()status:0 newState:0 11-25 18:02:13.735 19306-19306/com.putao.wd E/BluetoothFuncManager: onDfuCompleted info:C7:6B:39:0C:26:9A 11-25 18:02:14.775 19306-20534/com.putao.wd E/BluetoothFuncManager: disconnect() 11-25 18:02:35.435 19306-19306/com.putao.wd E/BluetoothFuncManager: disconnect() 11-25 18:02:35.535 19306-19317/com.putao.wd E/BluetoothFuncManager: onLeScan bluetoothDevice:C7:6B:39:0C:26:99 11-25 18:02:35.655 19306-21052/com.putao.wd E/BluetoothFuncManager: onConnectionStateChange()status:0 newState:2 11-25 18:02:35.665 19306-19641/com.putao.wd E/BluetoothFuncManager: onServicesDiscovered()status:0 11-25 18:02:35.775 19306-20534/com.putao.wd E/OtaUpgradeActivity: startOTA() 11-25 18:02:35.775 19306-20534/com.putao.wd W/ContextImpl: Failed to ensure directory: /storage/sdcard1/Android/data/com.putao.wd/files 11-25 18:02:35.785 19306-20534/com.putao.wd W/ContextImpl: Failed to ensure directory: /storage/sdcard1/Android/data/com.putao.wd/files 11-25 18:02:37.725 19306-19306/com.putao.wd E/BluetoothFuncManager: startOTAUpgrade() 11-25 18:02:39.795 19306-19306/com.putao.wd E/BluetoothFuncManager: onDfuProcessStarting info:C7:6B:39:0C:26:99 11-25 18:02:42.095 19306-21052/com.putao.wd E/DfuImpl: Characteristic write error: 3 11-25 18:02:42.095 19306-22790/com.putao.wd E/DfuBaseService: Unable to write Op Code 1 (error 3) 11-25 18:02:42.095 19306-19306/com.putao.wd E/BluetoothFuncManager: onDeviceDisconnecting info:C7:6B:39:0C:26:99 11-25 18:02:42.705 19306-19306/com.putao.wd E/BluetoothFuncManager: onError error:3 message:GATT WRITE NOT PERMIT 11-25 18:02:42.775 19306-19306/com.putao.wd E/BluetoothFuncManager: disconnect()