Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

OutOfMemory with Nitrokey Pro #1936

Closed
szszszsz opened this issue Oct 12, 2016 · 20 comments · Fixed by #2182
Closed

OutOfMemory with Nitrokey Pro #1936

szszszsz opened this issue Oct 12, 2016 · 20 comments · Fixed by #2182
Assignees

Comments

@szszszsz
Copy link

szszszsz commented Oct 12, 2016

Application crashes when I insert Nitrokey Pro and try to use it as a security token to generate key. Same was after clearing the stick with factory reset command (done using Nitrokey App).
Please let me know how can I create / extract the logs.

App version: 4.2 beta 1 (42000)
Android 6.0.1, Galaxy S6
Nitrokey Pro v0.7 (OTG USB)
Frequency: High (9/10)

Scenario:

  1. Insert Pro stick
  2. Open application
  3. Tap Manage my keys
  4. Tap USE SECURITY TOKEN
    4a. Red led on device flashes 2 times
  5. Application crashes
@szszszsz
Copy link
Author

szszszsz commented Oct 12, 2016

Calling possibly interested: @jans23 @nmikhailov

@Valodim
Copy link
Member

Valodim commented Oct 12, 2016

I take it this report is yours? Did you click on report?

java.lang.RuntimeException: An error occurred while executing doInBackground()
    at android.os.AsyncTask$3.done(AsyncTask.java:309)
    at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:354)
    at java.util.concurrent.FutureTask.setException(FutureTask.java:223)
    at java.util.concurrent.FutureTask.run(FutureTask.java:242)
    at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:234)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
    at java.lang.Thread.run(Thread.java:818)
Caused by: java.lang.OutOfMemoryError: Failed to allocate a 1763896344 byte allocation with 16777216 free bytes and 240MB until OOM
    at org.sufficientlysecure.keychain.securitytoken.usb.CcidTransceiver.receive(CcidTransceiver.java:139)
    at org.sufficientlysecure.keychain.securitytoken.usb.CcidTransceiver.receiveRaw(CcidTransceiver.java:50)
    at org.sufficientlysecure.keychain.securitytoken.usb.CcidTransceiver.iccPowerOn(CcidTransceiver.java:81)
    at org.sufficientlysecure.keychain.securitytoken.usb.tpdu.T1TpduProtocol.<init>(T1TpduProtocol.java:41)
    at org.sufficientlysecure.keychain.securitytoken.usb.UsbTransport.configureProtocol(UsbTransport.java:219)
    at org.sufficientlysecure.keychain.securitytoken.usb.UsbTransport.connect(UsbTransport.java:179)
    at org.sufficientlysecure.keychain.securitytoken.SecurityTokenHelper.connectToDevice(SecurityTokenHelper.java:157)
    at org.sufficientlysecure.keychain.ui.base.BaseSecurityTokenActivity.handleSecurityToken(BaseSecurityTokenActivity.java:437)
    at org.sufficientlysecure.keychain.ui.base.BaseSecurityTokenActivity$1.doInBackground(BaseSecurityTokenActivity.java:171)
    at org.sufficientlysecure.keychain.ui.base.BaseSecurityTokenActivity$1.doInBackground(BaseSecurityTokenActivity.java:161)

@szszszsz
Copy link
Author

Yes, I uploaded it with a comment.

@Valodim
Copy link
Member

Valodim commented Oct 12, 2016

That's probably it then. Haha, it tries to allocate 1.6GB of memory. Interesting

@nmikhailov
Copy link
Member

Thanks, I will work on it.

On Oct 12, 2016 18:08, "Vincent Breitmoser" notifications@github.com
wrote:

That's probably it then. Haha, it tries to allocate 1.6GB of memory.
Interesting


You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#1936 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/ABgpCFQ28Cq_rWnyjKTYy7dwpmjZCk15ks5qzL-4gaJpZM4KUnbm
.

@szszszsz
Copy link
Author

If I can retest or take additional logs then please let me know.
@Valodim I wanted to confirm is it this the one exactly, but I cannot find it in adb logrotate. Should I upload whole file here or is there sufficient info already?

@Valodim
Copy link
Member

Valodim commented Oct 12, 2016

Info should be good. Thanks for the thorough report!

@dschuermann dschuermann changed the title Crash on using Nitrokey Pro as a security token OutOfMemory with Nitrokey Pro Feb 8, 2017
@dschuermann dschuermann added the bug label Feb 8, 2017
@jans23
Copy link

jans23 commented Feb 16, 2017

@nmikhailov Is there anything we can do to help you solving this issue?

@tulir
Copy link

tulir commented Mar 1, 2017

I was able to import a private key stub of the key on my Nitrokey (#1833 (comment)) and it seemed to work at first, but it crashes once enter my PIN trying to decrypt something. (Nexus 5X, Android 7.1.1, Open Keychain 4.2.4)

@jonathancross
Copy link

Hi @nmikhailov Any updates?

@szszszsz
Copy link
Author

Hi!
I have just retested the issue with 4.5 (45000) on Pro 0.7 and sent a crash report. If I can provide any more details or help then let me know.

@techge
Copy link

techge commented Aug 25, 2017

I am using Pro 0.8 and Android 7.1 with OpenKeychain 4.5.
I do not get a full crash as described above, but the same behaviour mentioned by @szszszsz on #1937 (comment)

@Valodim
Copy link
Member

Valodim commented Sep 5, 2017

I'd work on this but I don't have the first idea of what's happening :)

@nmikhailov any insight?

@Artox
Copy link

Artox commented Oct 7, 2017

Looks like I am affected too, dumping a stacktrace here just in case it might contain a hint:

10-07 14:56:27.832  1786  1833 I ActivityManager: Displayed org.sufficientlysecure.keychain/.ui.CreateKeyActivity: +198ms (total +8s415ms)
10-07 14:56:27.834  1786  1822 D ActivityTrigger: ActivityTrigger activityStopTrigger 
10-07 14:56:27.836  4284  4284 D Launcher: onStop
10-07 14:56:27.836  4284  4284 D QuickPage: leaveQuickPageEditMode: true false false
10-07 14:56:27.836  4284  4284 D Launcher: mAppWidgetHost.stopListening()
10-07 14:56:28.256  9299  9305 I art     : Do partial code cache collection, code=29KB, data=29KB
10-07 14:56:28.257  9299  9305 I art     : After code cache collection, code=26KB, data=28KB
10-07 14:56:28.257  9299  9305 I art     : Increasing code cache capacity to 128KB
10-07 14:56:28.406  9299  9305 I art     : Do partial code cache collection, code=61KB, data=47KB
10-07 14:56:28.407  9299  9305 I art     : After code cache collection, code=56KB, data=46KB
10-07 14:56:28.407  9299  9305 I art     : Increasing code cache capacity to 256KB
10-07 14:56:28.442  4032  8488 I IcingInternalCorpora: EventIndexer: starting incremental update
10-07 14:56:28.446  4032  8488 I IcingInternalCorpora: EventIndexer: 0 added, 0 removed, 0 changed, 212 unchanged, 0 errors.
10-07 14:56:28.446  4032  8488 I IcingInternalCorpora: EventIndexer: finished after 4 ms.
10-07 14:56:28.472   666  3719 E ANDR-PERF-OPTSHANDLER: perf_lock_rel: updated /sys/class/scsi_host/host0/../../../clkscale_enable with 1
10-07 14:56:28.472   666  3719 E ANDR-PERF-OPTSHANDLER:  return value 2
10-07 14:56:28.474   666  3719 E ANDR-PERF-RESOURCEQS: Failed to reset optimization [3, 0]
10-07 14:56:29.194  8919  9455 I art     : Starting a blocking GC Alloc
10-07 14:56:29.194  8919  9455 I art     : Starting a blocking GC Alloc
10-07 14:56:29.208  8919  9455 I art     : Alloc sticky concurrent mark sweep GC freed 426(21KB) AllocSpace objects, 0(0B) LOS objects, 32% free, 20MB/30MB, paused 301us total 14.523ms
10-07 14:56:29.208  8919  9455 I art     : Starting a blocking GC Alloc
10-07 14:56:29.224  8919  9455 I art     : Alloc partial concurrent mark sweep GC freed 1212(73KB) AllocSpace objects, 3(5MB) LOS objects, 40% free, 15MB/25MB, paused 291us total 15.331ms
10-07 14:56:29.224  8919  9455 I art     : Starting a blocking GC Alloc
10-07 14:56:29.237  8919  9455 I art     : Alloc concurrent mark sweep GC freed 95(4KB) AllocSpace objects, 0(0B) LOS objects, 40% free, 15MB/25MB, paused 245us total 13.090ms
10-07 14:56:29.237  8919  9455 I art     : Forcing collection of SoftReferences for 1GB allocation
10-07 14:56:29.237  8919  9455 I art     : Starting a blocking GC Alloc
10-07 14:56:29.249  8919  9455 I art     : Alloc concurrent mark sweep GC freed 3(72B) AllocSpace objects, 0(0B) LOS objects, 39% free, 15MB/25MB, paused 107us total 11.041ms
10-07 14:56:29.249  8919  9455 W art     : Throwing OutOfMemoryError "Failed to allocate a 1980396612 byte allocation with 10719060 free bytes and 240MB until OOM"
10-07 14:56:29.249  8919  9455 I art     : Starting a blocking GC Alloc
10-07 14:56:29.249  8919  9455 I art     : Starting a blocking GC Alloc
10-07 14:56:29.251  8919  9455 I art     : Starting a blocking GC Alloc
10-07 14:56:29.257  8919  9455 I art     : Alloc partial concurrent mark sweep GC freed 12(1000B) AllocSpace objects, 0(0B) LOS objects, 40% free, 15MB/25MB, paused 109us total 6.421ms
10-07 14:56:29.257  8919  9455 I art     : Starting a blocking GC Alloc
10-07 14:56:29.268  8919  9455 I art     : Alloc concurrent mark sweep GC freed 3(72B) AllocSpace objects, 0(0B) LOS objects, 39% free, 15MB/25MB, paused 104us total 10.495ms
10-07 14:56:29.268  8919  9455 I art     : Forcing collection of SoftReferences for 1GB allocation
10-07 14:56:29.268  8919  9455 I art     : Starting a blocking GC Alloc
10-07 14:56:29.278  8919  9455 I art     : Alloc concurrent mark sweep GC freed 7(880B) AllocSpace objects, 0(0B) LOS objects, 40% free, 15MB/25MB, paused 103us total 10.124ms
10-07 14:56:29.278  8919  9455 I art     : Starting a blocking GC HomogeneousSpaceCompact
10-07 14:56:29.288  8919  9455 I art     : HomogeneousSpaceCompact marksweep + semispace GC freed 2(48B) AllocSpace objects, 0(0B) LOS objects, 39% free, 15MB/25MB, paused 9.967ms total 9.967ms
10-07 14:56:29.288  8919  9455 W art     : Throwing OutOfMemoryError "Failed to allocate a 1980396612 byte allocation with 10719060 free bytes and 240MB until OOM"
10-07 14:56:29.289  8919  9455 E AndroidRuntime: FATAL EXCEPTION: AsyncTask #2
10-07 14:56:29.289  8919  9455 E AndroidRuntime: Process: org.sufficientlysecure.keychain, PID: 8919
10-07 14:56:29.289  8919  9455 E AndroidRuntime: java.lang.RuntimeException: An error occurred while executing doInBackground()
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at android.os.AsyncTask$3.done(AsyncTask.java:325)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:354)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at java.util.concurrent.FutureTask.setException(FutureTask.java:223)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at java.util.concurrent.FutureTask.run(FutureTask.java:242)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:243)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at java.lang.Thread.run(Thread.java:761)
10-07 14:56:29.289  8919  9455 E AndroidRuntime: Caused by: java.lang.OutOfMemoryError: Failed to allocate a 1980396612 byte allocation with 10719060 free bytes and 240MB until OOM
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at org.sufficientlysecure.keychain.securitytoken.usb.CcidTransceiver.receive(CcidTransceiver.java:139)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at org.sufficientlysecure.keychain.securitytoken.usb.CcidTransceiver.receiveRaw(CcidTransceiver.java:50)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at org.sufficientlysecure.keychain.securitytoken.usb.CcidTransceiver.iccPowerOn(CcidTransceiver.java:81)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at org.sufficientlysecure.keychain.securitytoken.usb.tpdu.T1TpduProtocol.<init>(T1TpduProtocol.java:41)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at org.sufficientlysecure.keychain.securitytoken.usb.UsbTransport.configureProtocol(UsbTransport.java:219)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at org.sufficientlysecure.keychain.securitytoken.usb.UsbTransport.connect(UsbTransport.java:179)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at org.sufficientlysecure.keychain.securitytoken.SecurityTokenHelper.connectToDevice(SecurityTokenHelper.java:191)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at org.sufficientlysecure.keychain.ui.base.BaseSecurityTokenActivity.handleSecurityToken(BaseSecurityTokenActivity.java:433)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at org.sufficientlysecure.keychain.ui.base.BaseSecurityTokenActivity$1.doInBackground(BaseSecurityTokenActivity.java:146)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at org.sufficientlysecure.keychain.ui.base.BaseSecurityTokenActivity$1.doInBackground(BaseSecurityTokenActivity.java:136)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at android.os.AsyncTask$2.call(AsyncTask.java:305)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        at java.util.concurrent.FutureTask.run(FutureTask.java:237)
10-07 14:56:29.289  8919  9455 E AndroidRuntime:        ... 4 more
10-07 14:56:29.289  8919  9455 D AppTracker: App Event: crash
10-07 14:56:29.293  1786  1797 W ActivityManager:   Force finishing activity org.sufficientlysecure.keychain/.ui.CreateKeyActivity
10-07 14:56:29.297  1786  1797 D ActivityTrigger: ActivityTrigger activityPauseTrigger 
10-07 14:56:29.298  8919  9455 I Process : Sending signal. PID: 8919 SIG: 9
10-07 14:56:29.301  4186  6118 D OPReportService: addMonitorFolder onEvent path=data_app_crash@2017-10-07-14_56_29_300.txt, event:128
10-07 14:56:29.311  1786  1822 D CompatibilityInfo: mCompatibilityFlags - 0
10-07 14:56:29.311  1786  1822 D CompatibilityInfo: applicationDensity - 420
10-07 14:56:29.311  1786  1822 D CompatibilityInfo: applicationScale - 1.0
10-07 14:56:29.313  1786  2440 W InputDispatcher: channel 'b7385 org.sufficientlysecure.keychain/org.sufficientlysecure.keychain.ui.CreateKeyActivity (server)' ~ Consumer closed input channel or an error occurred.  events=0x9
10-07 14:56:29.313  1786  2440 E InputDispatcher: channel 'b7385 org.sufficientlysecure.keychain/org.sufficientlysecure.keychain.ui.CreateKeyActivity (server)' ~ Channel is unrecoverably broken and will be disposed!
10-07 14:56:29.317  1786  3185 D CompatibilityInfo: mCompatibilityFlags - 0
10-07 14:56:29.317  1786  3185 D CompatibilityInfo: applicationDensity - 420
10-07 14:56:29.317  1786  3185 D CompatibilityInfo: applicationScale - 1.0
10-07 14:56:29.323  1786  1796 D CompatibilityInfo: mCompatibilityFlags - 0
10-07 14:56:29.323  1786  1796 D CompatibilityInfo: applicationDensity - 420
10-07 14:56:29.323  1786  1796 D CompatibilityInfo: applicationScale - 1.0
10-07 14:56:29.334  1786  9458 D DropBoxManagerService: file :: /data/system/dropbox/data_app_crash@2017-10-07-14_56_29_300.txt
10-07 14:56:29.342  1786  4235 D GraphicsStats: Buffer count: 28
10-07 14:56:29.342  1786  3279 I WindowManager: WIN DEATH: Window{b7385 u0 org.sufficientlysecure.keychain/org.sufficientlysecure.keychain.ui.CreateKeyActivity}
10-07 14:56:29.342  1786  3279 W InputDispatcher: Attempted to unregister already unregistered input channel 'b7385 org.sufficientlysecure.keychain/org.sufficientlysecure.keychain.ui.CreateKeyActivity (server)'
10-07 14:56:29.342  4135  4147 E NfcService: applyRouting -5
10-07 14:56:29.342  4135  4147 D NfcService: applyRouting - enter force = false mScreenState = 3
10-07 14:56:29.343  1786  4236 D EmbryoManager: prepare org.sufficientlysecure.keychain
10-07 14:56:29.343  1786  4236 I ActivityManager: Process org.sufficientlysecure.keychain (pid 8919) has died
10-07 14:56:29.343  1786  4236 D ActivityManager: get process top duration : org.sufficientlysecure.keychain:sync, duration : 0
10-07 14:56:29.343  1786  4236 D ActivityManager: get process top duration : org.sufficientlysecure.keychain:UsbEventReceiverActivityProcess, duration : 293
10-07 14:56:29.343  1786  4236 D ActivityManager: get process top duration : org.sufficientlysecure.keychain, duration : 95

@Valodim
Copy link
Member

Valodim commented Oct 8, 2017

Hey there. I worked on this a while. I don't have a stick that exhibits this particular problem, but I might have found the cause.

So what happens is that before even the IccPowerOn message is sent to initialize the usb connection, the Nitrokey Pro sends 64 bytes of data thorugh the BulkIn endpoint. It's always exactly 64 bytes, and doesn't start with a parseable header or anything I could make any sense of from the CCID or 7816-3/4 specs. A Yubikey I plug in via USB doesn't send these bytes, either.

I suspect the reason for the OOM is that these bytes were under certain circumstances taken as a valid reply to the IccPowerOn message, and subsequently the ATR received from the actual IccPowerOn call was interpreted as the response to the next called XferBlock.

I did some work on this, cleaning up the code and adding more checks for consistency (sequence numbers, header names, error bits, etc), and this might fix the problem. The previous code had a "after sending IccPowerOn, just catch all exceptions for some time until we get a reply that looks vaguely like what we expected". I simply skip all incoming data before sending the IccPowerOn command now, which is slightly less hacky and seems to work fine for me:

https://github.com/open-keychain/open-keychain/commits/usb-refactor

The bytes are slightly changing every time, but some are also constant:

a78ae8aaf717cbbfecc7cb88a6f6910c56418514b6aaa0b8750555142bae39823210a22bfa3f73f9278bb74b2c95f65b134452ad236ea23ad0d75617ac843d29
a78ae88af6074b3f6cc7cb88a6f7910c56418514b2aaa0b8750555042aa639823210a26bfa3f73f9a78bb74bac95f65b136450ad236ea23ad0d75617ac863d39
a78ae88af707cbbb6cc5cb8826f7d10c56418514b2aaa0ba750515142ba639a23210a22bfa3f73f1a783b74b2c91f65b134452ad336ea23ad0d75217ac843c29

Someone else reported getting these bytes:

fa2e651a767541df360a8b2a1314857c890d51c16ade92891f57051846876584caca8202f4d705878e8e81cc4d36c76d650a155d2eb8fb2d74f30af7e48f86ad

@szszszsz You work on the Nitrokey firmware, right? Any ideas what these 64 bytes could be? :) (also ping @af-anssi and @nmikhailov)

@szszszsz
Copy link
Author

szszszsz commented Oct 9, 2017

Hi @Valodim ! Thank you for investigating this! Your explanation of the OOM's cause is quite reasonable. Indeed I work with the firmware but on the HID side mostly hence I do not have any ideas yet, but I will forward this to proper person.

@tulir
Copy link

tulir commented Oct 9, 2017

I just realized that my backup Nitrokey Pro (now promoted to main key) works just fine, while the other one causes this crash. I bought both Nitrokeys at the same time around a year ago. I can test things with both keys if needed.

@dschuermann
Copy link
Member

@tulir @techge @Artox @szszszsz Can you all please try our newest beta version and report if it now works? You can be part of the beta channel by visiting this special link: https://play.google.com/apps/testing/org.sufficientlysecure.keychain

@tulir
Copy link

tulir commented Oct 17, 2017

Both of my Nitrokeys work now. Thanks!

@szszszsz
Copy link
Author

It is not crashing now on my setup:

4.8-beta.1 (48000)
Nitrokey Pro v0.7

Thank you!

CC @jonathancross @jans23

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

9 participants