Failed Binder Transactions

[msg555]

Hi all,

I'm working on a deterministic record and replay extension to the Dalvik VM.  My modifications to the Android stack are mostly in libdvm with limited modifications to libcore and libnative_helper.  All of the applications I am using are pretty standard and run well without my modifications to the DalvikVM.

I'm having an issue where occasionally I'll get the below message:

E/JavaBinder(  375): !!! FAILED BINDER TRANSACTION !!!

while running an application (usually it's the launcher).  I'm not really sure what could be wrong or where to start debugging this.  When this happens on the launcher it's usually just after starting an Intent.  There don't appear to be any other related messages in logcat, even with verbose logging from libandroid_runtime and libbinder.

The only other information I can get come from kernel logs.

From dmesg around the time of the error:
<6>[  425.974082] binder: 375:379 refcount change on invalid ref 27
<6>[  425.974293] binder: 375:379 refcount change on invalid ref 27
<6>[  427.205309] binder: 375:379 got transaction with invalid handle, 27
<6>[  427.205532] binder: 375:379 transaction failed 29201, size 92-4

It seems that the 29201 field is suppose to be an error number.  It looks like it ought to be a small integer from the BinderDriverReturnProtocol enum which it clearly isn't.  I have no idea if the 'invalid ref' messages are relevant.

From /sys/kernel/debug/binder/failed_transaction_log:

13379: call  from 375:379 to 229:0 node 458 handle 1 size 92:4

From /sys/kernel/debug/binder/state:

proc 375
  thread 375: l 00
  thread 379: l 00
  thread 380: l 12
  thread 382: l 11
  thread 492: l 00
  thread 1060: l 11
  node 1588: u000b26d0 c000b26b0 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 1268: u000ed830 c00117820 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2645: u001a9a38 c001a9a18 hs 1 hw 1 ls 0 lw 0 is 2 iw 2 proc 385 229
  node 1631: u001b1010 c001b0f78 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2326: u001f0e68 c0020c0a0 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2341: u0020c510 c0020c4f0 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2425: u00239058 c0020ce98 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2440: u002390c8 c002390a8 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2449: u00239138 c00239118 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2469: u002391a8 c00239188 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2479: u00239380 c00239360 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2483: u002393f0 c002393d0 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2539: u00239748 c0028b778 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2900: u0025f780 c0025f760 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2804: u00271378 c00270348 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  node 2643: u0028d740 c001a99f8 hs 1 hw 1 ls 0 lw 0 is 1 iw 1 proc 229
  ref 1263: desc 0 node 1 s 1 w 1 d (null)
  ref 1266: desc 1 node 458 s 1 w 1 d (null)
  ref 1274: desc 2 node 547 s 1 w 1 d (null)
  ref 1275: desc 3 node 454 s 1 w 1 d (null)
  ref 1276: desc 4 node 532 s 1 w 1 d (null)
  ref 1282: desc 5 node 1281 s 1 w 1 d (null)
  ref 1395: desc 6 node 971 s 1 w 1 d (null)
  ref 1420: desc 7 node 28 s 1 w 1 d (null)
  ref 1423: desc 8 node 41 s 1 w 1 d (null)
  ref 1573: desc 9 node 963 s 1 w 1 d (null)
  ref 1679: desc 10 node 705 s 1 w 1 d (null)
  ref 2476: desc 11 node 508 s 1 w 1 d (null)
  ref 2641: desc 12 node 595 s 1 w 1 d (null)
  ref 2799: desc 13 node 2798 s 1 w 1 d (null)
  ref 13303: desc 14 node 13302 s 1 w 1 d (null)
  ref 2853: desc 15 node 2852 s 1 w 1 d (null)
  ref 2857: desc 16 node 2856 s 1 w 1 d (null)
  ref 2898: desc 17 node 653 s 1 w 1 d (null)
  ref 7482: desc 18 node 7458 s 1 w 1 d (null)
  ref 7483: desc 19 node 7462 s 1 w 1 d (null)
  ref 7484: desc 20 node 7466 s 1 w 1 d (null)
  ref 7485: desc 21 node 7470 s 1 w 1 d (null)
  ref 7486: desc 22 node 7474 s 1 w 1 d (null)
  ref 7487: desc 23 node 7478 s 1 w 1 d (null)
  ref 7877: desc 24 node 7865 s 1 w 1 d (null)
  ref 7878: desc 25 node 7869 s 1 w 1 d (null)
  ref 7879: desc 26 node 7873 s 1 w 1 d (null)
  ref 11434: desc 28 node 1157 s 1 w 1 d db76ac40
  buffer 13376: ebc00028 size 4:0 delivered
  buffer 13378: ebc00054 size 8:0 delivered

Any guesses as to what might be happening or how to go about debugging it would be greatly appreciated.

-Mark

[msg555]

I've realized now that the binder system is aware of thread and process ids which I've messed around a bit with.  In particular no binder calls are made on the thread that is created after the fork from zygote (i.e. no tid matches its pid).  Is it possible that is a problem?

It's also possible (but it seems unlikely) that some calls into the binder system that come from the same Java thread could actually be made on different threads.  As far as I can tell this isn't happening, however.

Also I guess I should mention that I'm working with CyanogenMod 7 (gingerbread).

-Mark