TC75: EMDK service unstable / failure to create DataWedge profile

Hello.

 

We are experiencing major problems with the EMDK service and the DataWedge service.

 

In our applications on the TC75 we are using some EMDK APIs, for example to create the DataWedge profile for barcode scanning, to set the system time, to disable the BT pairing dialogue and to install or upgrade APKs.

Sometimes, after a number of successful EMDK API calls, any further API call does not execute correctly anymore.

We then have to warm boot the TC75 to get EMDK API calls working again.

 

Another problem we recently see on TC75 devices here on our devices but also on customers devices, is that DataWedge profiles are sometimes not created successfully.

For example after a manual reset of the DataWedge profiles, the Velocity profile is sometimes not created again when the Velocity application is started.

 

To investigate these problems with a simple application I compiled the "ProfileDataCapture" sample (from Data Capture - Zebra Technologies Online Documentation) and tested it on my TC75.

After several times starting and leaving the sample application I could reproduce a permanent error.The application always displays "Profile initialization failed" when started.

In logcat I see these entries:

 

03-15 13:28:50.981 7319-7319/? D/com.symbol.emdk.emdkservice.barcode.SvcScanEventCallback: SvcScanEventCallback::barcodeManager

03-15 13:28:50.981 7319-7319/? D/dd:BT:: SvcBluetoothScanner::registerConnectionNotification

03-15 13:28:50.981 7319-7319/? D/dd:BT:: SvcBluetoothScanner::unregisterConnectionNotification

03-15 13:28:50.981 7319-7319/? D/com.symbol.emdk.emdkservice.EMDKService: The EMDKService was created.

03-15 13:28:50.981 7319-7319/? D/com.symbol.emdk.emdkservice.EMDKService: The AIDLProfileService was binded.

03-15 13:28:50.981 7319-7319/? D/com.symbol.emdk.emdkservice.MxServiceConnection: Binding Mx srvice

03-15 13:28:50.981 13335-13335/com.symbol.profiledatacapturesample1 D/com.symbol.emdk.EMDKServiceConnection: The EMDK Service will be connected soon (asynchronus call)!

03-15 13:28:50.991 7319-7319/? D/com.symbol.emdk.emdkservice.ProfileService: getVersion - Entering

03-15 13:28:50.991 7319-7319/? D/com.symbol.emdk.emdkservice.ProfileService: getVersion - Leaving

03-15 13:28:50.991 7319-7319/? D/EmdkService: EMDK Version=4.0.2.0

03-15 13:28:50.991 7319-7319/? D/MxVersionHandler: MxVersionHandler Constructor

03-15 13:28:50.991 945-945/? D/PhoneStatusBar: setSystemUiVisibility vis=0 mask=ffffffff oldVal=400 newVal=0 diff=400

03-15 13:28:50.991 945-945/? D/PhoneStatusBar: hiding the MENU button

03-15 13:28:51.001 13335-13335/com.symbol.profiledatacapturesample1 D/com.symbol.emdk.EMDKServiceConnection: The EMDK Service is now connected!

03-15 13:28:51.011 7319-8409/? D/com.symbol.emdk.emdkservice.ProfileService: initializeProfileService - starts

03-15 13:28:51.011 7319-8409/? D/com.symbol.emdk.emdkservice.ProfileHandler: ProfileHandler - Entering

03-15 13:28:51.032 7319-8409/? D/com.symbol.emdk.emdkservice.ProfileHandler: ProfileHandler - Leaving

03-15 13:28:51.032 7319-8409/? D/com.symbol.emdk.emdkservice.ProfileService: initializeProfileService - ends

03-15 13:28:51.062 13335-13335/com.symbol.profiledatacapturesample1 E/HAL: hw_get_module_by_class path = /system/lib/hw/gralloc.msm8960.so

03-15 13:28:51.092 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: createProfile - Entering

03-15 13:28:51.092 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: createProfile - profileName=DataCaptureProfile-1

03-15 13:28:51.092 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: createProfile - profileNameCriteria.length=1

03-15 13:28:51.092 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: profileNameCriteria.length>1 else block

03-15 13:28:51.092 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isBarcodePresentInProfile - Enetring

03-15 13:28:51.102 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isBarcodePresentInProfile - Before expr.evaluate

03-15 13:28:51.102 13335-13335/com.symbol.profiledatacapturesample1 I/ActivityManager: Timeline: Activity_idle id: android.os.BinderProxy@41d72b28 time:12936676

03-15 13:28:51.112 808-892/? I/ActivityManager: Displayed com.symbol.profiledatacapturesample1/.MainActivity: +188ms

03-15 13:28:51.122 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isBarcodePresentInProfile - After expr.evaluate

03-15 13:28:51.122 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isBarcodePresentInProfile - result!=null

03-15 13:28:51.122 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isBarcodePresentInProfile - After profileNode.getParentNode().getChildNodes()

03-15 13:28:51.122 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isBarcodePresentInProfile - Leaving

03-15 13:28:51.122 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isBarcodePresentInProfile=true

03-15 13:28:51.122 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isMxPresentInProfile - Enetring

03-15 13:28:51.122 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isMxPresentInProfile - Before expr.evaluate

03-15 13:28:51.142 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isMxPresentInProfile - After expr.evaluate

03-15 13:28:51.142 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isMxPresentInProfile - result!=null

03-15 13:28:51.142 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isMxPresentInProfile - After profileNode.getParentNode().getChildNodes()

03-15 13:28:51.142 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: isMxPresentInProfile - Leaving

03-15 13:28:51.142 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: >>>creating a profile<<<

03-15 13:28:51.162 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: >>>check if profile is found<<<

03-15 13:28:51.162 7319-9849/? D/com.symbol.emdk.emdkservice.ProfileHandler: >>>Creating a profile from XML only<<<

03-15 13:28:51.162 7319-9849/? D/com.symbol.emdk.emdkservice.DatabaseHelper: exportProfileToDB Entering

03-15 13:28:51.232 1217-17614/? E/AndroidRuntime: ERROR: thread detach failed

03-15 13:28:51.272 808-892/? I/ActivityManager: Timeline: Activity_windows_visible id: ActivityRecord{41ad5ef0 u0 com.symbol.profiledatacapturesample1/.MainActivity t102} time:12936847

03-15 13:28:51.322 1217-1217/? E/Image-JNI: Imager enable true..

03-15 13:28:51.432 189-17741/? E/mm-camera: [CAM] calibration file did NOT exist!!!

03-15 13:28:51.432 189-17741/? W/linker: libmmcamera_faceproc.so has text relocations. This is wasting memory and is a security risk. Please fix.

03-15 13:28:51.442 1217-1217/? E/ImagerControl: TransferI2C mIOControlFunction Failed retry

03-15 13:28:51.512 1217-1217/? E/QualCommAdapter: ISS v4lInitMmap Success

03-15 13:28:51.542 1217-1217/? D/dalvikvm: GC_FOR_ALLOC freed 1833K, 40% free 6810K/11228K, paused 29ms, total 29ms

03-15 13:28:51.542 1217-1217/? D/libimgkit: sysflags 38

03-15 13:28:51.552 1217-1217/? E/SE4750Control: PERF IC-Acquisition Mode +

03-15 13:28:51.562 1217-1217/? E/ImagerControl: TransferI2C mIOControlFunction Failed retry

03-15 13:28:51.572 1217-1217/? I/Image-JNI: LogDebugLevel=1

03-15 13:28:51.582 1217-1217/? D/ScanningProfile: enabling SimulScan plug-in

03-15 13:28:53.684 7319-9849/? E/SQLiteLog: (5) database is locked

03-15 13:28:53.684 7319-9849/? E/SQLiteDatabase: Failed to open database '/enterprise/device/settings/datawedge/autoimport/dwprofile_DataCaptureProfile-1.tmp'.

                                                 android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5): , while compiling: PRAGMA journal_mode

                                                     at android.database.sqlite.SQLiteConnection.nativePrepareStatement(Native Method)

                                                     at android.database.sqlite.SQLiteConnection.acquirePreparedStatement(SQLiteConnection.java:889)

                                                     at android.database.sqlite.SQLiteConnection.executeForString(SQLiteConnection.java:634)

                                                     at android.database.sqlite.SQLiteConnection.setJournalMode(SQLiteConnection.java:320)

                                                     at android.database.sqlite.SQLiteConnection.setWalModeFromConfiguration(SQLiteConnection.java:294)

                                                     at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:215)

                                                     at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:193)

                                                     at android.database.sqlite.SQLiteConnectionPool.openConnectionLocked(SQLiteConnectionPool.java:463)

                                                     at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:185)

                                                     at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:177)

                                                     at android.database.sqlite.SQLiteDatabase.openInner(SQLiteDatabase.java:804)

                                                     at android.database.sqlite.SQLiteDatabase.open(SQLiteDatabase.java:789)

                                                     at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:694)

                                                     at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:669)

                                                     at com.symbol.emdk.emdkservice.DatabaseHelper.exportProfileToDB(DatabaseHelper.java:140)

                                                     at com.symbol.emdk.emdkservice.ProfileHandler.createProfile(ProfileHandler.java:1588)

                                                     at com.symbol.emdk.emdkservice.ProfileHandler.doSetProfile(ProfileHandler.java:1083)

                                                     at com.symbol.emdk.emdkservice.ProfileService.setProfile(ProfileService.java:325)

                                                     at com.symbol.emdk.emdkservice.IEMDKService$Stub.onTransact(IEMDKService.java:81)

                                                     at android.os.Binder.execTransact(Binder.java:404)

                                                     at dalvik.system.NativeStart.run(Native Method)

03-15 13:28:53.684 7319-9849/? W/System.err: android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5): , while compiling: PRAGMA journal_mode

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteConnection.nativePrepareStatement(Native Method)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteConnection.acquirePreparedStatement(SQLiteConnection.java:889)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteConnection.executeForString(SQLiteConnection.java:634)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteConnection.setJournalMode(SQLiteConnection.java:320)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteConnection.setWalModeFromConfiguration(SQLiteConnection.java:294)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:215)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:193)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteConnectionPool.openConnectionLocked(SQLiteConnectionPool.java:463)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:185)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:177)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteDatabase.openInner(SQLiteDatabase.java:804)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteDatabase.open(SQLiteDatabase.java:789)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:694)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:669)

03-15 13:28:53.684 7319-9849/? W/System.err:     at com.symbol.emdk.emdkservice.DatabaseHelper.exportProfileToDB(DatabaseHelper.java:140)

03-15 13:28:53.684 7319-9849/? W/System.err:     at com.symbol.emdk.emdkservice.ProfileHandler.createProfile(ProfileHandler.java:1588)

03-15 13:28:53.684 7319-9849/? W/System.err:     at com.symbol.emdk.emdkservice.ProfileHandler.doSetProfile(ProfileHandler.java:1083)

03-15 13:28:53.684 7319-9849/? W/System.err:     at com.symbol.emdk.emdkservice.ProfileService.setProfile(ProfileService.java:325)

03-15 13:28:53.684 7319-9849/? W/System.err:     at com.symbol.emdk.emdkservice.IEMDKService$Stub.onTransact(IEMDKService.java:81)

03-15 13:28:53.684 7319-9849/? W/System.err:     at android.os.Binder.execTransact(Binder.java:404)

03-15 13:28:53.684 7319-9849/? W/System.err:     at dalvik.system.NativeStart.run(Native Method)

03-15 13:28:54.135 169-905/? D/ALSADevice: standby: handle 0xb7a91720 h 0x0

03-15 13:28:54.135 169-905/? V/ALSADevice: standby handle h 0xb7aa8f90

 

It looks like that there is a lock on the SQLite database for DataWedge profiles.

 

In another case I got a message box on the screen indicating that EMDK service had stopped.

 

Device data:

Device 'TC75'

Android version '4.4.3'

Kernel version '3.4.0'

Build Id '01-23257-K-14-04-00-MV'

MX Framework: 5.0.10

EMDK service: 4.0.2.0

DataWedge: 3.1.40

Imager firmware: PAABVC02-001-R00

 

How do we get these problems fixed?