svg loading segfaults on nexus 5x

[maho]

also it segfaults on some quite new Xiaomi.

adb log:

2017-06-01 13:05:05.921 ASSERT: DEBUG : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
2017-06-01 13:05:05.921 ASSERT: DEBUG : Build fingerprint: 'google/bullhead/bullhead:7.1.2/N2G47O/3852959:user/release-keys'
2017-06-01 13:05:05.921 ASSERT: DEBUG : Revision: 'rev_1.0'
2017-06-01 13:05:05.921 ASSERT: DEBUG : ABI: 'arm'
2017-06-01 13:05:05.922 ASSERT: DEBUG : pid: 10781, tid: 10820, name: SDLThread  >>> org.test.myapp <<<
2017-06-01 13:05:05.922 ASSERT: DEBUG : signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x34
2017-06-01 13:05:05.922 ASSERT: DEBUG : r0 d2260654  r1 00000000  r2 d495e240  r3 e1ce820c
2017-06-01 13:05:05.922 ASSERT: DEBUG : r4 d495e294  r5 00008be7  r6 00000001  r7 00000060
2017-06-01 13:05:05.922 ASSERT: DEBUG : r8 d47f6500  r9 d495e294  sl 00000000  fp 00000000
2017-06-01 13:05:05.922 ASSERT: DEBUG : ip 00000000  sp d514eda8  lr e1bda1ff  pc e1bda204  cpsr 80070030
2017-06-01 13:05:05.931 ASSERT: DEBUG : backtrace:
2017-06-01 13:05:05.932 ASSERT: DEBUG : #00 pc 000d3204  /vendor/lib/egl/libGLESv2_adreno.so
2017-06-01 13:05:05.932 ASSERT: DEBUG : #01 pc 000d79bb  /vendor/lib/egl/libGLESv2_adreno.so (_ZN21EsxGlApiParamValidate14GlDrawElementsEP11EsxDispatchjijPKv+122)
2017-06-01 13:05:05.932 ASSERT: DEBUG : #02 pc 00096f83  /vendor/lib/egl/libGLESv2_adreno.so (glDrawElements+34)
2017-06-01 13:05:05.932 ASSERT: DEBUG : #03 pc 00003417  /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/batching.so

Full log in https://pastebin.com/A0kt1pq2

Code which segfaults: https://github.com/mahomahomaho/kivent-segfault-issue (it's a bit modified example no 11). I have commented out

     size_of_batches: 786, 
     max_batches: 400,
     size_of_component_block: 786

because they caused memory error before app started on that android. And decreased isze of gameworld and indexes. Maybe it's the reason? What should be proper values?

Anyway - it doesn't crash on all androids, only on Nexus 5x, some Xiaomi (I don't know exact data) so far.

Steps to reproduce:

1. clone https://github.com/mahomahomaho/kivent-segfault-issue
2. buildozer andoird debug
3. upload .apk to nexus5x or similar and run

[maho]

What I discovered, is that in this line: https://github.com/kivy/kivent/blob/master/modules/core/kivent_core/rendering/batching.pyx#L215 - indices.data_size is ~182000 on Nexus, while 96 on other phones and on linux.

I have no idea where such strange indices.data_size comes from

[Kovak]

Ok a little bit of data dump to help solve this, not certain on the exact cause yet

The maximum number of indices that can be uploaded in ES2 is 65,535.

The size of a batch should be set so that it is not greater than 65535 * the size of the vertex format. This is the most important number to set when it comes to rendering, otherwsie batching could try to make a too large of batch.

This issue also reminds me of: https://github.com/kivy/kivy/issues/3693

[maho]

oh man, I have no idea how to access to indices memory ;)

But I noticed that on linux I have also indices.data_size=1828864 , but ony first time, and apparently it doesn't make any problem for OpenGL, next calls have data_size=96

[Kovak]

I wonder if we have something that is not initialized properly on the first call.

[maho]

I think so, set_index_count_for_frame is called with index_count=48 , BUT draw_frame is called BEFORE set_index_count_for_frame.....

[Kovak]

ooo that is not supposed to happen! Will need to make sure things happen in the right order.

[maho]

At first I thought that that first draw_frame tries to draw junk before something is initialized. So I make draw_frame just skip until set_index_count_for_frame is called. And still segfaults.

I would try to dump memory in vertices and indices, but ... I have no idea how should I do it. Any hint? Or better - code to copy&paste? :)

[maho]

ok, I know how to dump, and I will dump soon.

And I know now, that it's not matter of not initialized batch, and it's NOT matter of SVG. I tried example with polydraw (no svg involved) and result is the same.

I will post memdump soon I hope.

[maho]

So, I ran https://github.com/kivy/kivent/tree/master/examples/12_drawing_shapes example, with decreased memory in .kv to 600kb , and with enabled DEBUG logging, and with this branch of kivent: https://github.com/mahomahomaho/kivent/tree/testcase-segfault-logging on Nexus5x,

It dumped buffer bound by indices.bind() and vertices.bind() - log is in https://transfer.sh/ryjYP/TestObject_Log_LG_Nexus_5X_real_06-06-2017_10-34-31.txt

Log is about creating simple triangle on the screen - it generates creating buffer with 262 thousands of zeroes.

[maho]

it's definitively not matter of not initialized data_size of index_vbo. When I set it to 0 at the start, first call to glDrawElements passes and next fails. While that next looks legit:

14:20:53 I python : [DEBUG  ] glBufferSubData(target=34963 data_size=0L) (will dump first 300)
14:20:53 I python : [INFO   ] glDrawElements(mode=4 indices.data_size=0)
14:20:53 I python : [INFO   ] after glDrawElements
14:20:53 I python : [INFO   ] after vertices undbind
14:20:53 I python : [INFO   ] after indices unbind
14:20:53 I python : [DEBUG  ] Renderer.update for batch_key=4294967295
14:20:53 I python : [DEBUG  ] batches = [<kivent_core.rendering.batching.IndexedBatch object at 0xd6b860f0>]
14:20:53 I python : [DEBUG  ] for batch = <kivent_core.rendering.batching.IndexedBatch object at 0xd6b860f0>, static_rendering=False force_update=False
14:20:53 I python : [DEBUG  ] set_index_count_for_frame(index_count=3)
14:20:53 I python : [DEBUG  ] self.current_frame=2 self.frame_count=1
14:20:53 I python : [DEBUG  ] glBufferSubData(target=34962 data_size=262144L) (will dump first 300)
14:20:53 I python : 00000000: 00 C0 11 44 00 40 3E 44  FF 00 00 FF 00 40 37 44  ...D.@>D.....@7D
14:20:53 I python : 00000010: 00 40 3E 44 00 FF 00 FF  00 80 24 44 00 C0 63 44  .@>D......$D..cD
14:20:53 I python : 00000020: 00 00 FF FF 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 00000030: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 00000040: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 00000050: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 00000060: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 00000070: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 00000080: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 00000090: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 000000A0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 000000B0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 000000C0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 000000D0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 000000E0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 000000F0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 00000100: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 00000110: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
14:20:53 I python : 00000120: 00 00 00 00 00 00 00 00  00 00 00 00              ............
14:20:53 I python : [DEBUG  ] glBufferData(target=34963 data_size=6L usage=35040) (will dump first 300)
14:20:53 I python : 00000000: 00 00 01 00 02 00                                 ......
14:20:53 I python : [INFO   ] glDrawElements(mode=4 indices.data_size=6)
14:20:53 I python : --------- beginning of crash
14:20:53 A libc : Fatal signal 11 (SIGSEGV), code 1, fault addr 0x34 in tid 14163 (SDLThread)
14:20:53 W  : debuggerd: handling request: pid=14143 uid=10133 gid=10133 tid=14163
14:20:53 W debuggerd : type=1400 audit(0.0:68): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:69): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:70): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:71): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:72): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:73): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:74): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:75): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:76): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:77): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:78): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:79): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:80): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:81): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:82): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:83): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:84): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:85): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:86): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:87): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 W debuggerd : type=1400 audit(0.0:88): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=385504 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
14:20:53 I TOOLKIT SERVICE : Request body '{"id":"1496830939971","type":"GET_SCREEN_ORIENTATION"}'
14:20:53 I DEVICE MANAGER : {"id":"1496830939971","type":"GET_SCREEN_ORIENTATION"}
14:20:53 I TOOLKIT SERVICE : Responding to client with: '{"id":"1496830939971","orientation":"PORTRAIT"}'
14:20:53 I art : Starting a blocking GC Explicit
14:20:53 A DEBUG : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
14:20:53 A DEBUG : Build fingerprint: 'google/bullhead/bullhead:7.1.2/N2G47O/3852959:user/release-keys'
14:20:53 A DEBUG : Revision: 'rev_1.0'
14:20:53 A DEBUG : ABI: 'arm'
14:20:53 A DEBUG : pid: 14143, tid: 14163, name: SDLThread  >>> org.test.myapp <<<
14:20:53 A DEBUG : signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x34
14:20:53 A DEBUG : r0 d984e254  r1 00000000  r2 d9ccee80  r3 e78b720c
14:20:53 A DEBUG : r4 d9cceed4  r5 00008be7  r6 00000001  r7 00000060
14:20:53 A DEBUG : r8 da5523c0  r9 d9cceed4  sl 00000000  fp 00000000
14:20:53 A DEBUG : ip 00000000  sp db560d78  lr e77a91ff  pc e77a9204  cpsr 800f0030
14:20:53 A DEBUG : backtrace:
14:20:53 A DEBUG : #00 pc 000d3204  /vendor/lib/egl/libGLESv2_adreno.so
14:20:53 A DEBUG : #01 pc 000d79bb  /vendor/lib/egl/libGLESv2_adreno.so (_ZN21EsxGlApiParamValidate14GlDrawElementsEP11EsxDispatchjijPKv+122)
14:20:53 A DEBUG : #02 pc 00096f83  /vendor/lib/egl/libGLESv2_adreno.so (glDrawElements+34)
14:20:53 A DEBUG : #03 pc 00006e27  /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/batching.so

I'm not an expert of float representation of vertices, but I don't see anything wrong with data in logs. Any idea why it fails in adreno but not in other opengl providers? maybe we don't call something which should be called first?

[maho]

and one thought - maybe there is something wrong with shader?

[Kovak]

I don't think the issue is with the way the vertex data is formatted. The traceback seems to point to possibly a bug in the gl implementation. I'm seeing a lot of similar issues on SO with the adreno drivers. There is probably a work around we can do if we can discover what it is.

One thing that might help, if you set debug = True before compiling https://github.com/kivy/kivent/blob/master/modules/core/kivent_core/gameworld.pyx#L25

you should get debug logs for all our GL calls which might help us track down an error.

[maho]

I didn't find any effect of setting gameworld.debug to True but, when I set https://github.com/kivy/kivy/blob/master/kivy/graphics/cgl.pyx#L94 , then I get blank screen in nexus5.

[maho]

I also get blank screen when I set KIVY_GL_DEBUG=1 in linux

I think my queue of ideas drained out.

I read somewhere that OpenGL ES is ansynchronous. Is it possible that glDrawElements is executed before glSetBuffer takes effect? Or sth like that?

[Kovak]

You get no additional logs when you set gameworld.debug to True and recompile? The other KIVY_GL_DEBUG is different. OpenGL of all types is technically a client, server interaction; but there are additional limits on that with ES and most versions of GL prior to the newest where only a single thread can communicate with the GL context. It is far more likely that there is a bug in the Adreno drivers and we need to find a work around (adreno drivers are notoriously inconsistent and incomplete)

[maho]

I don't see anything more than I added. Below is the log, and code which is run (kivent both with app) is in https://github.com/mahomahomaho/kivent/tree/testcase-segfault-logging (app is examples/12-....)

2017-06-12 11:50:53.853 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253940612","closePopups":true}'
2017-06-12 11:50:53.855 INFO:   PlayCommon : [451] com.google.android.play.a.g.e(220): Preparing logs for uploading
2017-06-12 11:50:53.856 INFO:   PlayCommon : [451] com.google.android.play.a.g.e(224): No file ready to send
2017-06-12 11:50:53.899 WARN:   libEGL : EGLNativeWindowType 0x7eceaf8210 disconnect failed
2017-06-12 11:50:54.441 DEBUG:  AndroidRuntime : >>>>>> START com.android.internal.os.RuntimeInit uid 2000 <<<<<<
2017-06-12 11:50:54.446 DEBUG:  AndroidRuntime : CheckJNI is OFF
2017-06-12 11:50:54.524 DEBUG:  ICU : No timezone override file found: /data/misc/zoneinfo/current/icu/icu_tzdata.dat
2017-06-12 11:50:54.559 INFO:   Radio-JNI : register_android_hardware_Radio DONE
2017-06-12 11:50:54.571 DEBUG:  AndroidRuntime : Calling main entry com.android.commands.pm.Pm
2017-06-12 11:50:54.604 INFO:   art : System.exit called, status: 0
2017-06-12 11:50:54.604 INFO:   AndroidRuntime : VM exiting with result code 0.
2017-06-12 11:50:54.610 WARN:   MessageQueue : Handler (android.os.Handler) {917e108} sending message to a Handler on a dead thread
2017-06-12 11:50:54.610 WARN:   MessageQueue : java.lang.IllegalStateException: Handler (android.os.Handler) {917e108} sending message to a Handler on a dead thread
2017-06-12 11:50:54.610 WARN:   MessageQueue : at android.os.MessageQueue.enqueueMessage(MessageQueue.java:543)
2017-06-12 11:50:54.610 WARN:   MessageQueue : at android.os.Handler.enqueueMessage(Handler.java:643)
2017-06-12 11:50:54.610 WARN:   MessageQueue : at android.os.Handler.sendMessageAtTime(Handler.java:612)
2017-06-12 11:50:54.610 WARN:   MessageQueue : at android.os.Handler.sendMessageDelayed(Handler.java:582)
2017-06-12 11:50:54.610 WARN:   MessageQueue : at android.os.Handler.post(Handler.java:338)
2017-06-12 11:50:54.610 WARN:   MessageQueue : at android.os.ResultReceiver$MyResultReceiver.send(ResultReceiver.java:57)
2017-06-12 11:50:54.610 WARN:   MessageQueue : at com.android.internal.os.IResultReceiver$Stub.onTransact(IResultReceiver.java:58)
2017-06-12 11:50:54.610 WARN:   MessageQueue : at android.os.Binder.execTransact(Binder.java:565)
2017-06-12 11:50:55.384 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:50:55.439 INFO:   art : Explicit concurrent mark sweep GC freed 148(8KB) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 250us total 54.670ms
2017-06-12 11:50:56.889 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:50:56.942 INFO:   art : Explicit concurrent mark sweep GC freed 76(4KB) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 293us total 53.141ms
2017-06-12 11:50:57.997 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253944759","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:57.998 INFO:   DEVICE MANAGER : {"id":"1497253944759","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.002 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253944759","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.011 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253944774","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.011 INFO:   DEVICE MANAGER : {"id":"1497253944774","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.014 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253944774","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.061 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253944824","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.061 INFO:   DEVICE MANAGER : {"id":"1497253944824","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.063 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253944824","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.112 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253944873","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.112 INFO:   DEVICE MANAGER : {"id":"1497253944873","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.116 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253944873","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.168 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253944929","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.168 INFO:   DEVICE MANAGER : {"id":"1497253944929","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.173 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253944929","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.224 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253944985","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.224 INFO:   DEVICE MANAGER : {"id":"1497253944985","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.230 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253944985","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.281 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253945042","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.281 INFO:   DEVICE MANAGER : {"id":"1497253945042","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.286 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253945042","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.341 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253945101","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.341 INFO:   DEVICE MANAGER : {"id":"1497253945101","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.345 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253945101","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.393 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:50:58.400 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253945158","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.400 INFO:   DEVICE MANAGER : {"id":"1497253945158","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.404 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253945158","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.448 INFO:   art : Explicit concurrent mark sweep GC freed 73(3KB) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 345us total 54.521ms
2017-06-12 11:50:58.451 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253945214","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.451 INFO:   DEVICE MANAGER : {"id":"1497253945214","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.453 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253945214","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.500 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253945261","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.500 INFO:   DEVICE MANAGER : {"id":"1497253945261","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.505 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253945261","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.554 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253945315","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.554 INFO:   DEVICE MANAGER : {"id":"1497253945315","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.559 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253945315","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.610 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253945371","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.610 INFO:   DEVICE MANAGER : {"id":"1497253945371","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.615 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253945371","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.667 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253945428","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.667 INFO:   DEVICE MANAGER : {"id":"1497253945428","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.673 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253945428","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.724 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253945485","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.724 INFO:   DEVICE MANAGER : {"id":"1497253945485","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.731 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253945485","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.778 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253945541","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.778 INFO:   DEVICE MANAGER : {"id":"1497253945541","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.781 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253945541","orientation":"PORTRAIT"}'
2017-06-12 11:50:58.831 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253945593","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:58.831 INFO:   DEVICE MANAGER : {"id":"1497253945593","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:58.836 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253945593","orientation":"PORTRAIT"}'
2017-06-12 11:50:59.208 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253945968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:59.208 INFO:   DEVICE MANAGER : {"id":"1497253945968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:59.213 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253945968","orientation":"PORTRAIT"}'
2017-06-12 11:50:59.707 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253946468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:50:59.708 INFO:   DEVICE MANAGER : {"id":"1497253946468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:50:59.712 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253946468","orientation":"PORTRAIT"}'
2017-06-12 11:50:59.896 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:50:59.942 INFO:   art : Explicit concurrent mark sweep GC freed 54(2840B) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 287us total 45.942ms
2017-06-12 11:51:00.204 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253946968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:00.204 INFO:   DEVICE MANAGER : {"id":"1497253946968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:00.207 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253946968","orientation":"PORTRAIT"}'
2017-06-12 11:51:00.707 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253947468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:00.708 INFO:   DEVICE MANAGER : {"id":"1497253947468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:00.712 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253947468","orientation":"PORTRAIT"}'
2017-06-12 11:51:01.207 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253947968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:01.207 INFO:   DEVICE MANAGER : {"id":"1497253947968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:01.212 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253947968","orientation":"PORTRAIT"}'
2017-06-12 11:51:01.398 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:01.445 INFO:   art : Explicit concurrent mark sweep GC freed 8(272B) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 257us total 46.696ms
2017-06-12 11:51:01.707 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253948468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:01.708 INFO:   DEVICE MANAGER : {"id":"1497253948468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:01.711 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253948468","orientation":"PORTRAIT"}'
2017-06-12 11:51:02.208 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253948968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:02.208 INFO:   DEVICE MANAGER : {"id":"1497253948968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:02.213 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253948968","orientation":"PORTRAIT"}'
2017-06-12 11:51:02.708 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253949468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:02.708 INFO:   DEVICE MANAGER : {"id":"1497253949468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:02.712 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253949468","orientation":"PORTRAIT"}'
2017-06-12 11:51:02.899 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:02.946 INFO:   art : Explicit concurrent mark sweep GC freed 8(272B) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 251us total 46.751ms
2017-06-12 11:51:03.207 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253949968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:03.207 INFO:   DEVICE MANAGER : {"id":"1497253949968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:03.213 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253949968","orientation":"PORTRAIT"}'
2017-06-12 11:51:03.707 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253950468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:03.707 INFO:   DEVICE MANAGER : {"id":"1497253950468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:03.712 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253950468","orientation":"PORTRAIT"}'
2017-07-24 11:51:04.258 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253951017","type":"GET_SCREEN_ORIENTATION"}'
2017-07-12 11:51:04.258 INFO:   DEVICE MANAGER : {"id":"1497253951017","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:04.265 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253951017","orientation":"PORTRAIT"}'
2017-06-12 11:51:04.400 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:04.449 INFO:   art : Explicit concurrent mark sweep GC freed 8(272B) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 362us total 48.045ms
2017-06-12 11:51:04.708 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253951468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:04.709 INFO:   DEVICE MANAGER : {"id":"1497253951468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:04.714 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253951468","orientation":"PORTRAIT"}'
2017-06-12 11:51:05.207 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253951968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:05.207 INFO:   DEVICE MANAGER : {"id":"1497253951968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:05.212 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253951968","orientation":"PORTRAIT"}'
2017-06-12 11:51:05.708 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253952468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:05.708 INFO:   DEVICE MANAGER : {"id":"1497253952468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:05.714 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253952468","orientation":"PORTRAIT"}'
2017-06-12 11:51:05.903 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:05.957 INFO:   art : Explicit concurrent mark sweep GC freed 8(272B) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 356us total 53.180ms
2017-06-12 11:51:06.209 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253952968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:06.209 INFO:   DEVICE MANAGER : {"id":"1497253952968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:06.214 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253952968","orientation":"PORTRAIT"}'
2017-06-12 11:51:06.707 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253953468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:06.708 INFO:   DEVICE MANAGER : {"id":"1497253953468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:06.712 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253953468","orientation":"PORTRAIT"}'
2017-06-12 11:51:07.209 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253953968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:07.209 INFO:   DEVICE MANAGER : {"id":"1497253953968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:07.212 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253953968","orientation":"PORTRAIT"}'
2017-06-12 11:51:07.408 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:07.456 INFO:   art : Explicit concurrent mark sweep GC freed 8(272B) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 420us total 47.587ms
2017-06-12 11:51:07.713 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253954468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:07.713 INFO:   DEVICE MANAGER : {"id":"1497253954468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:07.715 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253954468","orientation":"PORTRAIT"}'
2017-06-12 11:51:08.207 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253954968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:08.207 INFO:   DEVICE MANAGER : {"id":"1497253954968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:08.213 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253954968","orientation":"PORTRAIT"}'
2017-06-12 11:51:08.709 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253955468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:08.709 INFO:   DEVICE MANAGER : {"id":"1497253955468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:08.715 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253955468","orientation":"PORTRAIT"}'
2017-06-12 11:51:08.911 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:08.960 INFO:   art : Explicit concurrent mark sweep GC freed 8(272B) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 334us total 48.884ms
2017-06-12 11:51:09.209 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253955968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:09.209 INFO:   DEVICE MANAGER : {"id":"1497253955968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:09.216 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253955968","orientation":"PORTRAIT"}'
2017-06-12 11:51:09.709 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253956468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:09.709 INFO:   DEVICE MANAGER : {"id":"1497253956468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:09.715 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253956468","orientation":"PORTRAIT"}'
2017-06-12 11:51:10.207 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253956968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:10.207 INFO:   DEVICE MANAGER : {"id":"1497253956968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:10.212 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253956968","orientation":"PORTRAIT"}'
2017-06-12 11:51:10.347 DEBUG:  AndroidRuntime : >>>>>> START com.android.internal.os.RuntimeInit uid 2000 <<<<<<
2017-06-12 11:51:10.354 DEBUG:  AndroidRuntime : CheckJNI is OFF
2017-06-12 11:51:10.411 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:10.422 DEBUG:  ICU : No timezone override file found: /data/misc/zoneinfo/current/icu/icu_tzdata.dat
2017-06-12 11:51:10.451 INFO:   Radio-JNI : register_android_hardware_Radio DONE
2017-06-12 11:51:10.456 INFO:   art : Explicit concurrent mark sweep GC freed 8(272B) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 225us total 44.187ms
2017-06-12 11:51:10.462 DEBUG:  AndroidRuntime : Calling main entry com.android.commands.pm.Pm
2017-06-12 11:51:10.482 INFO:    : free_cache(9282121) avail 23970156544
2017-06-12 11:51:10.657 DEBUG:  WifiStateMachine : CMD_AUTO_CONNECT sup state DisconnectedState my state DisconnectedState nid=0 roam=false
2017-06-12 11:51:10.657 DEBUG:  WifiStateMachine : CMD_AUTO_CONNECT will save config -> "TestObject Devices" nid=0
2017-06-12 11:51:10.704 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253957468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:10.704 INFO:   DEVICE MANAGER : {"id":"1497253957468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:10.705 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253957468","orientation":"PORTRAIT"}'
2017-09-03 11:51:10.831 DEBUG:  WifiNetworkHistory : saving network history: "TestObject Devices"WPA_PSK gw: null Network Selection-status: NETWORK_SELECTION_ENABLED ephemeral=false choice:null link:0 status:2 nid:0 hasEverConnected: true
2017-04-12 11:00:10.840 DEBUG:  WifiStateMachine : CMD_AUTO_CONNECT did save config ->  nid=0
2017-06-12 11:51:10.843 INFO:   wpa_supplicant : wlan0: Trying to associate with SSID 'TestObject Devices'
2017-06-12 11:51:10.843 DEBUG:  WifiNetworkHistory : saving network history: "TestObject Devices"WPA_PSK gw: null Network Selection-status: NETWORK_SELECTION_ENABLED ephemeral=false choice:null link:0 status:2 nid:0 hasEverConnected: true
2017-06-12 11:51:10.918 INFO:   wpa_supplicant : wlan0: Associated with 92:2a:a8:48:62:19
2017-06-12 11:51:10.920 INFO:   wpa_supplicant : wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
2017-06-12 11:51:10.927 INFO:   wpa_supplicant : wlan0: WPA: Key negotiation completed with 92:2a:a8:48:62:19 [PTK=CCMP GTK=CCMP]
2017-06-12 11:51:10.927 INFO:   wpa_supplicant : wlan0: CTRL-EVENT-CONNECTED - Connection to 92:2a:a8:48:62:19 completed [id=0 id_str=%7B%22creatorUid%22%3A%2210124%22%2C%22configKey%22%3A%22%5C%22TestObject+Devices%5C%22WPA_PSK%22%7D]
2017-06-12 11:51:10.937 DEBUG:  ConnectivityService : registerNetworkAgent NetworkAgentInfo{ ni{[type: WIFI[], state: CONNECTING/CONNECTING, reason: (unspecified), extra: "TestObject Devices", failover: false, available: true, roaming: false, metered: false]}  network{103}  nethandle{442398067422}  lp{{LinkAddresses: []  Routes: [] DnsAddresses: [] Domains: null MTU: 0}}  nc{[ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps]}  Score{20}  everValidated{false}  lastValidated{false}  created{false} lingering{false} explicitlySelected{false} acceptUnvalidated{false} everCaptivePortalDetected{false} lastCaptivePortalDetected{false} }
2017-06-12 11:51:10.937 DEBUG:  ConnectivityService : NetworkAgentInfo [WIFI () - 103] EVENT_NETWORK_INFO_CHANGED, going from null to CONNECTING
2017-06-12 11:51:10.942 DEBUG:  wifi : APF version supported: 2
2017-06-12 11:51:10.942 DEBUG:  wifi : Maximum APF program size: 4096
2017-06-12 11:51:10.944 DEBUG:  WifiStateMachine : Start Dhcp Watchdog 4
2017-06-12 11:51:10.952 DEBUG:  WifiNative-wlan0 : configureNeighborDiscoveryOffload(true)
2017-06-12 11:51:10.967 DEBUG:  ApfFilter : (wlan0): begin monitoring
2017-06-12 11:51:10.981 DEBUG:  DhcpClient : Receive thread started
2017-06-12 11:51:10.986 DEBUG:  DhcpClient : Broadcasting DHCPDISCOVER
2017-06-12 11:51:11.038 INFO:   PackageManager.DexOptimizer : Running dexopt (dex2oat) on: /data/app/vmdl1326965938.tmp/base.apk pkg=org.test.myapp isa=arm vmSafeMode=false debuggable=true target-filter=interpret-only oatDir = /data/app/vmdl1326965938.tmp/oat sharedLibraries=null
2017-06-12 11:51:11.078 INFO:   dex2oat : /system/bin/dex2oat --compiler-filter=interpret-only -j4 --debuggable
2017-06-12 11:51:11.205 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253957968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:11.205 INFO:   DEVICE MANAGER : {"id":"1497253957968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:11.208 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253957968","orientation":"PORTRAIT"}'
2017-06-12 11:51:11.242 INFO:   dex2oat : dex2oat took 164.953ms (threads: 4) arena alloc=4KB (4688B) java alloc=252KB (258696B) native alloc=1180KB (1208512B) free=2MB (2985792B)
2017-06-12 11:51:11.444 DEBUG:  installd : Detected label change from u:object_r:system_data_file:s0 to u:object_r:app_data_file:s0:c512,c768 at /data/data/org.test.myapp; running recursive restorecon
2017-06-12 11:51:11.446 DEBUG:  installd : Detected label change from u:object_r:system_data_file:s0 to u:object_r:app_data_file:s0:c512,c768 at /data/user_de/0/org.test.myapp; running recursive restorecon
2017-06-12 11:51:11.451 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:11.579 INFO:   art : Explicit concurrent mark sweep GC freed 115731(6MB) AllocSpace objects, 25(828KB) LOS objects, 33% free, 16MB/25MB, paused 1.792ms total 128.140ms
2017-06-12 11:51:11.580 ERROR:   : Couldn't opendir /data/app/vmdl1326965938.tmp: No such file or directory
2017-06-12 11:51:11.603 INFO:   InputReader : Reconfiguring input devices.  changes=0x00000010
2017-06-12 11:51:11.611 WARN:   PackageManager : Unable to load service info ResolveInfo{1a7c626 mobicip.com.safeBrowserff/org.mozilla.gecko.fxa.authenticator.FxAccountAuthenticatorService m=0x108000}
2017-06-12 11:51:11.614 INFO:   art : System.exit called, status: 0
2017-06-12 11:51:11.614 INFO:   AndroidRuntime : VM exiting with result code 0.
2017-06-12 11:51:11.629 DEBUG:  CarrierSvcBindHelper : No carrier app for: 0
2017-06-12 11:51:11.630 DEBUG:  CarrierConfigLoader : mHandler: 9 phoneId: 0
2017-06-12 11:51:11.640 DEBUG:  RegisteredNfcFServicesCache : Service unchanged, not updating
2017-06-12 11:51:11.657 INFO:   Finsky : [1] com.google.android.finsky.utils.PermissionPolicies$PermissionPolicyService.onStartCommand(18): post-install permissions check for org.test.myapp
2017-06-12 11:51:11.663 WARN:   PackageManager : Unable to load service info ResolveInfo{6198f55 mobicip.com.safeBrowserff/org.mozilla.gecko.fxa.sync.FxAccountSyncService m=0x108000}
2017-06-12 11:51:11.670 INFO:   Finsky : [1] com.google.android.finsky.utils.ao.run(11): Package state data is missing for org.test.myapp
2017-06-12 11:51:11.676 INFO:   WearableService : onCreate - Wear is not available on this device.
2017-06-12 11:51:11.686 DEBUG:  WearableService : onGetService - Wear is not available on this device.
2017-06-12 11:51:11.689 ERROR:  Finsky : [1] com.google.android.finsky.wear.bl.a(3): onConnectionFailed: ConnectionResult{statusCode=API_UNAVAILABLE, resolution=null, message=null}
2017-06-12 11:51:11.691 WARN:   Finsky : [1] com.google.android.finsky.wear.aj.run(9): Dropping command=auto_install due to Gms not connected
2017-06-12 11:51:11.699 WARN:   Finsky : [1] com.google.android.finsky.wear.aj.run(9): Dropping command=send_installed_apps due to Gms not connected
2017-06-12 11:51:11.704 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253958468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:11.704 INFO:   DEVICE MANAGER : {"id":"1497253958468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:11.705 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253958468","orientation":"PORTRAIT"}'
2017-06-12 11:51:11.714 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253958478","type":"CLOSE_POPUPS"}'
2017-06-12 11:51:11.714 INFO:   DEVICE MANAGER : {"id":"1497253958478","type":"CLOSE_POPUPS"}
2017-06-12 11:51:11.718 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253958478","closePopups":true}'
2017-06-12 11:51:11.745 DEBUG:  Wear_Controller : Received broadcast action=android.intent.action.PACKAGE_ADDED and uri=org.test.myapp
2017-06-12 11:51:11.784 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253958549","type":"CLOSE_POPUPS"}'
2017-06-12 11:51:11.784 INFO:   DEVICE MANAGER : {"id":"1497253958549","type":"CLOSE_POPUPS"}
2017-06-12 11:51:11.786 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253958549","closePopups":true}'
2017-06-12 11:51:11.819 INFO:   Icing : App usage reports: 2
2017-06-12 11:51:11.819 INFO:   Icing : Usage reports 2 indexed 0 rejected 0 imm upload false
2017-06-12 11:51:11.831 INFO:   TOOLKIT SERVICE : Request body '{"package":"org.test.myapp","id":"1497253958594","type":"LAUNCH_APP"}'
2017-06-12 11:51:11.831 INFO:   DEVICE MANAGER : {"package":"org.test.myapp","id":"1497253958594","type":"LAUNCH_APP"}
2017-06-12 11:51:11.833 INFO:   art : Do full code cache collection, code=250KB, data=240KB
2017-06-12 11:51:11.834 INFO:   art : Starting a blocking GC JitCodeCache
2017-06-12 11:51:11.834 INFO:   art : After code cache collection, code=234KB, data=195KB
2017-06-12 11:51:11.835 INFO:   ActivityManager : START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10000000 pkg=org.test.myapp cmp=org.test.myapp/org.kivy.android.PythonActivity} from uid 10124 on display 0
2017-06-12 11:51:11.845 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253958594","launchApp":true}'
2017-06-12 11:51:11.854 INFO:   Icing : Usage reports 0 indexed 0 rejected 0 imm upload false
2017-06-12 11:51:11.859 INFO:   ActivityManager : Start proc 9536:org.test.myapp/u0a132 for activity org.test.myapp/org.kivy.android.PythonActivity
2017-06-12 11:51:11.862 INFO:   art : Late-enabling -Xcheck:jni
2017-06-12 11:51:11.914 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:11.940 INFO:   art : Explicit concurrent mark sweep GC freed 254(62KB) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 157us total 26.250ms
2017-06-12 11:51:11.941 INFO:   eLock : pkgname_before:com.google.android.googlequicksearchbox  class:org.test.myapp  isFingerActivityCreated:false   isCalling:false
2017-06-12 11:51:11.990 DEBUG:  DhcpClient : Received packet: 78:f8:82:9e:e9:a4 OFFER, ip /10.252.132.159, mask /255.255.240.0, DNS servers: /10.252.143.254 , gateways [/10.252.143.254] lease time 7200, domain localdomain
2017-06-12 11:51:11.991 DEBUG:  DhcpClient : Got pending lease: IP address 10.252.132.159/20 Gateway 10.252.143.254  DNS servers: [ 10.252.143.254 ] Domains localdomain DHCP server /10.252.143.254 Vendor info null lease 7200 seconds
2017-06-12 11:51:11.993 DEBUG:  DhcpClient : Broadcasting DHCPREQUEST ciaddr=0.0.0.0 request=10.252.132.159 serverid=10.252.143.254
2017-06-12 11:51:12.000 DEBUG:  DhcpClient : Received packet: 78:f8:82:9e:e9:a4 ACK: your new IP /10.252.132.159, netmask /255.255.240.0, gateways [/10.252.143.254] DNS servers: /10.252.143.254 , lease time 7200
2017-06-12 11:51:12.001 DEBUG:  DhcpClient : Confirmed lease: IP address 10.252.132.159/20 Gateway 10.252.143.254  DNS servers: [ 10.252.143.254 ] Domains localdomain DHCP server /10.252.143.254 Vendor info null lease 7200 seconds
2017-06-12 11:51:12.005 DEBUG:  WifiStateMachine : updateCapabilities for config:TestObject Devicesfalse,false
2017-06-12 11:51:12.005 DEBUG:  CommandListener : Setting iface cfg
2017-06-12 11:51:12.016 DEBUG:  WifiStateMachine : updateCapabilities for config:TestObject Devicesfalse,false
2017-06-12 11:51:12.016 DEBUG:  DhcpClient : Scheduling renewal in 3599s
2017-06-12 11:51:12.016 DEBUG:  DhcpClient : Scheduling rebind in 6299s
2017-06-12 11:51:12.016 DEBUG:  DhcpClient : Scheduling expiry in 7199s
2017-06-12 11:51:12.017 ERROR:  WifiNative-HAL : setBssidBlacklist cmd 3 size 0
2017-06-12 11:51:12.017 DEBUG:  wifi : configure BSSID black list request [4] = 0x7a75ce79e0
2017-06-12 11:51:12.017 DEBUG:  wifi : Added 0 bssids
2017-06-12 11:51:12.018 DEBUG:  ConnectivityService : NetworkAgentInfo [WIFI () - 103] EVENT_NETWORK_INFO_CHANGED, going from CONNECTING to CONNECTED
2017-06-12 11:51:12.020 DEBUG:  WifiStateMachine : updateCapabilities for config:TestObject Devicesfalse,false
2017-06-12 11:51:12.021 DEBUG:  ConnectivityService : Adding iface wlan0 to network 103
2017-06-12 11:51:12.032 ERROR:  WifiStateMachine : Did not find remoteAddress {10.252.143.254} in /proc/net/arp
2017-06-12 11:51:12.074 DEBUG:  ConnectivityService : Setting DNS servers for network 103 to [/10.252.143.254]
2017-06-12 11:51:12.093 DEBUG:  WifiNetworkAgent : NetworkAgent: Received signal strength thresholds: []
2017-06-12 11:51:12.093 DEBUG:  WifiNative-HAL : stopRssiMonitoring, cmdId 0
2017-06-12 11:51:12.094 DEBUG:  ConnectivityService : Switching to new default network: NetworkAgentInfo{ ni{[type: WIFI[], state: CONNECTED/CONNECTED, reason: (unspecified), extra: "TestObject Devices", failover: false, available: true, roaming: false, metered: false]}  network{103}  nethandle{442398067422}  lp{{InterfaceName: wlan0 LinkAddresses: [10.252.132.159/20,]  Routes: [fe80::/64 -> :: wlan0,10.252.128.0/20 -> 0.0.0.0 wlan0,0.0.0.0/0 -> 10.252.143.254 wlan0,] DnsAddresses: [10.252.143.254,] Domains: localdomain MTU: 0 TcpBufferSizes: 524288,6291456,8291456,524288,6291456,8291456}}  nc{[ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&FOREGROUND LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -31]}  Score{20}  everValidated{false}  lastValidated{false}  created{true} lingering{false} explicitlySelected{false} acceptUnvalidated{false} everCaptivePortalDetected{false} lastCaptivePortalDetected{false} }
2017-06-12 11:51:12.109 DEBUG:  NetworkMonitor/NetworkAgentInfo [WIFI () - 103] : PROBE_DNS OK 12ms, connectivitycheck.gstatic.com=216.58.208.35
2017-06-12 11:51:12.110 DEBUG:  NetworkMonitor/NetworkAgentInfo [WIFI () - 103] : PROBE_DNS OK 11ms, www.google.com=172.217.18.4
2017-06-12 11:51:12.153 DEBUG:  NetworkMonitor/NetworkAgentInfo [WIFI () - 103] : PROBE_HTTP http://connectivitycheck.gstatic.com/generate_204 time=36ms ret=204 headers={null=[HTTP/1.1 204 No Content], Content-Length=[0], Date=[Mon, 12 Jun 2017 07:51:12 GMT], X-Android-Received-Millis=[1497253872148], X-Android-Response-Source=[NETWORK 204], X-Android-Selected-Protocol=[http/1.1], X-Android-Sent-Millis=[1497253872133]}
2017-06-12 11:51:12.177 INFO:   WifiHAL : Fate Tx-Rx: Packet fate stats stop received
2017-06-12 11:51:12.182 WARN:   QCNEJ : |CORE| network available: 103
2017-06-12 11:51:12.183 DEBUG:  ConnectivityService : Sending CONNECTED broadcast for type 1 NetworkAgentInfo [WIFI () - 103] isDefaultNetwork=true
2017-06-12 11:51:12.188 WARN:   QCNEJ : |CORE| onAvailable: bind the process to WIFI
2017-06-12 11:51:12.189 WARN:   QCNEJ : |CORE| newLp: {InterfaceName: wlan0 LinkAddresses: [10.252.132.159/20,fe80::7af8:82ff:fe9e:e9a4/64,]  Routes: [fe80::/64 -> :: wlan0,10.252.128.0/20 -> 0.0.0.0 wlan0,0.0.0.0/0 -> 10.252.143.254 wlan0,] DnsAddresses: [10.252.143.254,] Domains: localdomain MTU: 0 TcpBufferSizes: 524288,6291456,8291456,524288,6291456,8291456}
2017-06-12 11:51:12.189 WARN:   QCNEJ : |CORE| curLp: {InterfaceName: wlan0 LinkAddresses: [10.252.132.159/20,fe80::7af8:82ff:fe9e:e9a4/64,]  Routes: [fe80::/64 -> :: wlan0,10.252.128.0/20 -> 0.0.0.0 wlan0,0.0.0.0/0 -> 10.252.143.254 wlan0,] DnsAddresses: [10.252.143.254,] Domains: localdomain MTU: 0}
2017-06-12 11:51:12.197 INFO:   Adreno : QUALCOMM build                   : 6818200, Idb2b4cb785
2017-06-12 11:51:12.197 INFO:   Adreno : Build Date                       : 11/18/16
2017-06-12 11:51:12.197 INFO:   Adreno : OpenGL ES Shader Compiler Version: XE031.09.00.04
2017-06-12 11:51:12.197 INFO:   Adreno : Local Branch                     : N25
2017-06-12 11:51:12.197 INFO:   Adreno : Remote Branch                    :
2017-06-12 11:51:12.197 INFO:   Adreno : Remote Branch                    :
2017-06-12 11:51:12.197 INFO:   Adreno : Reconstruct Branch               :
2017-06-12 11:51:12.202 DEBUG:  MusicLifecycle : com.google.android.music.net.NetworkConnectivityMonitor$NetworkChangedReceiver generated event: Broadcast received with context com.google.android.music.ui.PhoneMusicApplication@a7c68f1 and intent Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 (has extras) }
2017-06-12 11:51:12.203 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253958968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:12.203 INFO:   DEVICE MANAGER : {"id":"1497253958968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:12.204 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253958968","orientation":"PORTRAIT"}'
2017-06-12 11:51:12.214 DEBUG:  BugleThrottledAction : CountryCodeDetectorAction already scheduled in 38982ms, not scheduling it again.
2017-06-12 11:51:12.218 DEBUG:  RcsService : Never provisioned and provisioning is not allowed, skipped config update request
2017-06-12 11:51:12.217 INFO:   NetworkConnectivity : Network state changed: [type: WIFI[], state: CONNECTED/CONNECTED, reason: (unspecified), extra: "TestObject Devices", failover: false, available: true, roaming: false, metered: false]
2017-06-12 11:51:12.222 DEBUG:  NetworkMonitor/NetworkAgentInfo [WIFI () - 103] : PROBE_HTTPS https://www.google.com/generate_204 time=110ms ret=204 headers={null=[HTTP/1.1 204 No Content], Alt-Svc=[quic=":443"; ma=2592000; v="38,37,36,35"], Content-Length=[0], Date=[Mon, 12 Jun 2017 07:51:12 GMT], X-Android-Received-Millis=[1497253872221], X-Android-Response-Source=[NETWORK 204], X-Android-Selected-Protocol=[http/1.1], X-Android-Sent-Millis=[1497253872148]}
2017-06-12 11:51:12.223 DEBUG:  ConnectivityService : NetworkAgentInfo [WIFI () - 103] validation passed
2017-06-12 11:51:12.231 INFO:   NetworkPolicyMonitor : Download-ability status changed to (true) unmetered wifi/eth: true mobileOrMetered: false
2017-06-12 11:51:12.234 INFO:   OpenGLRenderer : Initialized EGL, version 1.4
2017-06-12 11:51:12.234 DEBUG:  OpenGLRenderer : Swap behavior 1
2017-06-12 11:51:12.237 DEBUG:  WifiNetworkHistory : saving network history: "TestObject Devices"WPA_PSK gw: null Network Selection-status: NETWORK_SELECTION_ENABLED ephemeral=false choice:null link:0 status:0 nid:0 hasEverConnected: true
2017-06-12 11:51:12.240 INFO:   NetworkPolicyMonitor : Stream-ability status changed to (true) unmetered wifi/eth: true mobileOrMetered: false
2017-06-12 11:51:12.398 INFO:   ActivityManager : Displayed org.test.myapp/org.kivy.android.PythonActivity: +550ms
2017-06-12 11:51:12.456 INFO:   PBSessionCacheImpl : Deleted sessionId[68803168747701] from persistence.
2017-06-12 11:51:12.493 INFO:   DeviceStateChecker : DeviceStateChecker cancelled
2017-06-12 11:51:12.494 INFO:   MicroDetector : Keeping mic open: false
2017-06-12 11:51:12.543 INFO:   MicroRecognitionRunner : Stopping hotword detection.
2017-06-12 11:51:12.543 INFO:   AudioController : internalShutdown
2017-06-12 11:51:12.544 INFO:   MicrophoneInputStream : mic_close com.google.android.apps.gsa.speech.audio.af@f52928
2017-06-12 11:51:12.591 DEBUG:  audio_hw_primary : disable_audio_route: usecase(8) reset and update mixer path: audio-record
2017-06-12 11:51:12.592 DEBUG:  audio_hw_primary : disable_snd_device: snd_device(63: voice-rec-mic)
2017-06-12 11:51:12.596 DEBUG:  sound_trigger_platform : platform_stdev_check_and_update_concurrency: concurrency active 0, tx 0, rx 0, concurrency session_allowed 1
2017-06-12 11:51:12.597 INFO:   SoundTriggerHwService::Module : void android::SoundTriggerHwService::Module::onCallbackEvent(const sp<android::SoundTriggerHwService::CallbackEvent> &) mClient == 0
2017-06-12 11:51:12.599 INFO:   MicroRecognitionRunner : Detection finished
2017-06-12 11:51:12.675 DEBUG:  GeckoPushGCM : Message received.  Processing on background thread.
2017-06-12 11:51:12.676 INFO:   GeckoPushService : Google Play Services GCM message received; delivering.
2017-06-12 11:51:12.676 WARN:   GeckoPushService : No chid found; ignoring message.
2017-06-12 11:51:12.704 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253959468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:12.704 INFO:   DEVICE MANAGER : {"id":"1497253959468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:12.706 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253959468","orientation":"PORTRAIT"}'
2017-06-12 11:51:12.789 INFO:   wpa_supplicant : TDLS: Invalid frame - payloadtype=1 category=240 action=10
2017-06-12 11:51:12.859 INFO:   Icing : Indexing 3E6BC02FD171012F08D51FB532CD7396824CE96F from com.google.android.gms
2017-06-12 11:51:12.911 INFO:   Icing : Indexing done 3E6BC02FD171012F08D51FB532CD7396824CE96F
2017-06-12 11:51:13.204 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253959968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:13.204 INFO:   DEVICE MANAGER : {"id":"1497253959968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:13.205 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253959968","orientation":"PORTRAIT"}'
2017-06-12 11:51:13.415 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:13.443 INFO:   art : Explicit concurrent mark sweep GC freed 557(67KB) AllocSpace objects, 2(40KB) LOS objects, 39% free, 18MB/30MB, paused 263us total 27.290ms
2017-06-12 11:51:13.594 WARN:   linker : /data/app/org.test.myapp-1/lib/arm/libpython2.7.so: is missing DT_SONAME will use basename as a replacement: "libpython2.7.so"
2017-06-12 11:51:13.617 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/lib-dynload/_io.so: is missing DT_SONAME will use basename as a replacement: "_io.so"
2017-06-12 11:51:13.618 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/lib-dynload/unicodedata.so: is missing DT_SONAME will use basename as a replacement: "unicodedata.so"
2017-06-12 11:51:13.619 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/lib-dynload/_ctypes.so: is missing DT_SONAME will use basename as a replacement: "_ctypes.so"
2017-06-12 11:51:13.649 INFO:   PythonActivity : Surface will NOT be transparent
2017-06-12 11:51:13.704 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253960468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:13.704 INFO:   DEVICE MANAGER : {"id":"1497253960468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:13.704 INFO:   sensors : batch
2017-06-12 11:51:13.706 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253960468","orientation":"PORTRAIT"}'
2017-06-12 11:51:13.708 INFO:   nanohub : queueBatch: sensor=1, handle=1, period=20000000, latency=0
2017-06-12 11:51:13.708 INFO:   sensors : activate
2017-06-12 11:51:13.709 INFO:   nanohub : queueActivate: sensor=1, handle=1, enable=1
2017-06-12 11:51:13.711 INFO:   nanohub : osLog: [BMI160] accSetRate: rate=51200, latency=19999744, state=3
2017-06-12 11:51:13.715 INFO:   SDL : SDL_Android_Init()
2017-06-12 11:51:13.715 INFO:   SDL : SDL_Android_Init() finished!
2017-06-12 11:51:13.715 INFO:   python : Initialize Python for Android
2017-06-12 11:51:13.715 INFO:   python : Changing directory to the one provided by ANDROID_ARGUMENT
2017-06-12 11:51:13.715 INFO:   python : /data/user/0/org.test.myapp/files/app
2017-06-12 11:51:13.715 INFO:   python : Preparing to initialize python
2017-06-12 11:51:13.715 INFO:   python : crystax_python does not exist
2017-06-12 11:51:13.722 INFO:   python : Initialized python
2017-06-12 11:51:13.722 INFO:   python : AND: Init threads
2017-06-12 11:51:13.724 INFO:   python : testing python print redirection
2017-06-12 11:51:13.725 INFO:   python : Setting up python from ANDROID_PRIVATE
2017-06-12 11:51:13.726 INFO:   python : ('Android path', ['/data/user/0/org.test.myapp/files/app/lib/python27.zip', '/data/user/0/org.test.myapp/files/app/lib/python2.7/', '/data/user/0/org.test.myapp/files/app/lib/python2.7/lib-dynload/', '/data/user/0/org.test.myapp/files/app/lib/python2.7/site-packages/', '/data/user/0/org.test.myapp/files/app'])
2017-06-12 11:51:13.741 INFO:   python : ('os.environ is', {'DOWNLOAD_CACHE': '/data/cache', 'EXTERNAL_STORAGE': '/sdcard', 'ANDROID_ENTRYPOINT': 'main.pyo', 'ANDROID_ASSETS': '/system/app', 'PYTHONPATH': '/data/user/0/org.test.myapp/files/app:/data/user/0/org.test.myapp/files/app/lib', 'ANDROID_APP_PATH': '/data/user/0/org.test.myapp/files/app', 'ANDROID_ROOT': '/system', 'SYSTEMSERVERCLASSPATH': '/system/framework/services.jar:/system/framework/ethernet-service.jar:/system/framework/wifi-service.jar', 'PYTHONOPTIMIZE': '2', 'ANDROID_DATA': '/data', 'PYTHONHOME': '/data/user/0/org.test.myapp/files/app', 'ANDROID_ARGUMENT': '/data/user/0/org.test.myapp/files/app', 'BOOTCLASSPATH': '/system/framework/core-oj.jar:/system/framework/core-libart.jar:/system/framework/conscrypt.jar:/system/framework/okhttp.jar:/system/framework/core-junit.jar:/system/framework/bouncycastle.jar:/system/framework/ext.jar:/system/framework/framework.jar:/system/framework/telephony-common.jar:/system/framework/voip-common.jar:/system/framework/ims-common.jar:/system/framework/apache-xml.jar:/system/framework/org.apache.http.legacy.boot.jar', 'ANDROID_SOCKET_zygote_secondary': '9', 'ASEC_MOUNTPOINT': '/mnt/asec', 'PATH': '/sbin:/vendor/bin:/system/sbin:/system/bin:/system/xbin', 'ANDROID_STORAGE': '/storage', 'ANDROID_BOOTLOGO': '1', 'ANDROID_PRIVATE': '/data/user/0/org.test.myapp/files', 'PYTHON_NAME': 'python'})
2017-06-12 11:51:13.741 INFO:   python : ('Android kivy bootstrap done. __name__ is', '__main__')
2017-06-12 11:51:13.767 INFO:   python : ['/data/user/0/org.test.myapp/files/app/lib/python2.7/site-packages', '/data/user/0/org.test.myapp/files/app/lib/site-python']
2017-06-12 11:51:13.767 INFO:   python : AND: Ran string
2017-06-12 11:51:13.767 INFO:   python : Run user program, change dir and execute entrypoint
2017-06-12 11:51:13.836 INFO:   python : [WARNING] [Config      ] Older configuration version detected (0 instead of 19)
2017-06-12 11:51:13.837 INFO:   python : [WARNING] [Config      ] Upgrading configuration in progress.
2017-06-12 11:51:13.842 INFO:   python : [INFO   ] [Logger      ] Record log in /data/user/0/org.test.myapp/files/app/.kivy/logs/kivy_17-06-12_0.txt
2017-06-12 11:51:13.842 INFO:   python : [INFO   ] [Kivy        ] v1.10.0
2017-06-12 11:51:13.842 INFO:   python : [INFO   ] [Python      ] v2.7.2 (default, Jun 10 2017, 12:12:30)
2017-06-12 11:51:13.843 INFO:   python : [GCC 4.8]
2017-06-12 11:51:13.847 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/_clock.so: is missing DT_SONAME will use basename as a replacement: "_clock.so"
2017-06-12 11:51:13.858 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/_event.so: is missing DT_SONAME will use basename as a replacement: "_event.so"
2017-06-12 11:51:13.859 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/properties.so: is missing DT_SONAME will use basename as a replacement: "properties.so"
2017-06-12 11:51:13.866 INFO:   python : [INFO   ] [Factory     ] 194 symbols loaded
2017-06-12 11:51:14.125 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/instructions.so: is missing DT_SONAME will use basename as a replacement: "instructions.so"
2017-06-12 11:51:14.128 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/buffer.so: is missing DT_SONAME will use basename as a replacement: "buffer.so"
2017-06-12 11:51:14.129 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/vertex.so: is missing DT_SONAME will use basename as a replacement: "vertex.so"
2017-06-12 11:51:14.130 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/cgl.so: is missing DT_SONAME will use basename as a replacement: "cgl.so"
2017-06-12 11:51:14.132 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/vbo.so: is missing DT_SONAME will use basename as a replacement: "vbo.so"
2017-06-12 11:51:14.133 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/compiler.so: is missing DT_SONAME will use basename as a replacement: "compiler.so"
2017-06-12 11:51:14.134 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/transformation.so: is missing DT_SONAME will use basename as a replacement: "transformation.so"
2017-06-12 11:51:14.135 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/shader.so: is missing DT_SONAME will use basename as a replacement: "shader.so"
2017-06-12 11:51:14.136 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/texture.so: is missing DT_SONAME will use basename as a replacement: "texture.so"
2017-06-12 11:51:14.137 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/context_instructions.so: is missing DT_SONAME will use basename as a replacement: "context_instructions.so"
2017-06-12 11:51:14.161 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/core/image/_img_sdl2.so: is missing DT_SONAME will use basename as a replacement: "_img_sdl2.so"
2017-06-12 11:51:14.165 INFO:   python : [INFO   ] [Image       ] Providers: img_tex, img_dds, img_sdl2, img_gif (img_pil, img_ffpyplayer ignored)
2017-06-12 11:51:14.167 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/fbo.so: is missing DT_SONAME will use basename as a replacement: "fbo.so"
2017-06-12 11:51:14.168 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/context.so: is missing DT_SONAME will use basename as a replacement: "context.so"
2017-06-12 11:51:14.169 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/opengl.so: is missing DT_SONAME will use basename as a replacement: "opengl.so"
2017-06-12 11:51:14.177 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/opengl_utils.so: is missing DT_SONAME will use basename as a replacement: "opengl_utils.so"
2017-06-12 11:51:14.179 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/vertex_instructions.so: is missing DT_SONAME will use basename as a replacement: "vertex_instructions.so"
2017-06-12 11:51:14.181 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/stencil_instructions.so: is missing DT_SONAME will use basename as a replacement: "stencil_instructions.so"
2017-06-12 11:51:14.183 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/gl_instructions.so: is missing DT_SONAME will use basename as a replacement: "gl_instructions.so"
2017-06-12 11:51:14.184 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/scissor_instructions.so: is missing DT_SONAME will use basename as a replacement: "scissor_instructions.so"
2017-06-12 11:51:14.185 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/weakproxy.so: is missing DT_SONAME will use basename as a replacement: "weakproxy.so"
2017-06-12 11:51:14.206 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253960968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:14.206 INFO:   DEVICE MANAGER : {"id":"1497253960968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:14.209 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253960968","orientation":"PORTRAIT"}'
2017-06-12 11:51:14.214 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/core/window/_window_sdl2.so: is missing DT_SONAME will use basename as a replacement: "_window_sdl2.so"
2017-06-12 11:51:14.227 INFO:   python : [INFO   ] [OSC         ] using <thread> for socket
2017-06-12 11:51:14.230 INFO:   python : [INFO   ] [Window      ] Provider: sdl2
2017-06-12 11:51:14.247 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/cgl_backend/cgl_glew.so: is missing DT_SONAME will use basename as a replacement: "cgl_glew.so"
2017-06-12 11:51:14.248 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/cgl_backend/cgl_gl.so: is missing DT_SONAME will use basename as a replacement: "cgl_gl.so"
2017-06-12 11:51:14.262 INFO:   python : [INFO   ] [GL          ] Using the "OpenGL ES 2" graphics system
2017-06-12 11:51:14.263 INFO:   python : [INFO   ] [GL          ] Backend used <gl>
2017-06-12 11:51:14.263 INFO:   python : [INFO   ] [GL          ] OpenGL version <OpenGL ES 3.2 V@145.0 (GIT@Idb2b4cb785)>
2017-06-12 11:51:14.263 INFO:   python : [INFO   ] [GL          ] OpenGL vendor <Qualcomm>
2017-06-12 11:51:14.263 INFO:   python : [INFO   ] [GL          ] OpenGL renderer <Adreno (TM) 418>
2017-06-12 11:51:14.264 INFO:   python : [INFO   ] [GL          ] OpenGL parsed version: 3, 2
2017-06-12 11:51:14.264 INFO:   python : [INFO   ] [GL          ] Texture max size <16384>
2017-06-12 11:51:14.264 INFO:   python : [INFO   ] [GL          ] Texture max units <16>
2017-06-12 11:51:14.301 INFO:   python : [INFO   ] [Window      ] auto add sdl2 input provider
2017-06-12 11:51:14.302 INFO:   python : [INFO   ] [Window      ] virtual keyboard not allowed, single mode, not docked
2017-06-12 11:51:14.303 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/memory_handlers/block.so: is missing DT_SONAME will use basename as a replacement: "block.so"
2017-06-12 11:51:14.304 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/memory_handlers/membuffer.so: is missing DT_SONAME will use basename as a replacement: "membuffer.so"
2017-06-12 11:51:14.305 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/memory_handlers/utils.so: is missing DT_SONAME will use basename as a replacement: "utils.so"
2017-06-12 11:51:14.306 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/memory_handlers/pool.so: is missing DT_SONAME will use basename as a replacement: "pool.so"
2017-06-12 11:51:14.306 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/memory_handlers/zone.so: is missing DT_SONAME will use basename as a replacement: "zone.so"
2017-06-12 11:51:14.307 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/memory_handlers/indexing.so: is missing DT_SONAME will use basename as a replacement: "indexing.so"
2017-06-12 11:51:14.308 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/memory_handlers/tests.so: is missing DT_SONAME will use basename as a replacement: "tests.so"
2017-06-12 11:51:14.309 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/vertex_format.so: is missing DT_SONAME will use basename as a replacement: "vertex_format.so"
2017-06-12 11:51:14.310 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/gl_debug.so: is missing DT_SONAME will use basename as a replacement: "gl_debug.so"
2017-06-12 11:51:14.311 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/frame_objects.so: is missing DT_SONAME will use basename as a replacement: "frame_objects.so"
2017-06-12 11:51:14.312 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/fixedvbo.so: is missing DT_SONAME will use basename as a replacement: "fixedvbo.so"
2017-06-12 11:51:14.313 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/cmesh.so: is missing DT_SONAME will use basename as a replacement: "cmesh.so"
2017-06-12 11:51:14.315 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/uix/cwidget.so: is missing DT_SONAME will use basename as a replacement: "cwidget.so"
2017-06-12 11:51:14.317 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/uix/gamescreens.so: is missing DT_SONAME will use basename as a replacement: "gamescreens.so"
2017-06-12 11:51:14.323 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/systems/gamesystem.so: is missing DT_SONAME will use basename as a replacement: "gamesystem.so"
2017-06-12 11:51:14.325 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/managers/resource_managers.so: is missing DT_SONAME will use basename as a replacement: "resource_managers.so"
2017-06-12 11:51:14.326 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/managers/game_manager.so: is missing DT_SONAME will use basename as a replacement: "game_manager.so"
2017-06-12 11:51:14.327 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/vertex_formats.so: is missing DT_SONAME will use basename as a replacement: "vertex_formats.so"
2017-06-12 11:51:14.328 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/model.so: is missing DT_SONAME will use basename as a replacement: "model.so"
2017-06-12 11:51:14.329 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/svg_loader.so: is missing DT_SONAME will use basename as a replacement: "svg_loader.so"
2017-06-12 11:51:14.330 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/graphics/tesselator.so: is missing DT_SONAME will use basename as a replacement: "tesselator.so"
2017-06-12 11:51:14.346 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/managers/entity_manager.so: is missing DT_SONAME will use basename as a replacement: "entity_manager.so"
2017-06-12 11:51:14.347 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/memory_handlers/zonedblock.so: is missing DT_SONAME will use basename as a replacement: "zonedblock.so"
2017-06-12 11:51:14.348 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/systems/staticmemgamesystem.so: is missing DT_SONAME will use basename as a replacement: "staticmemgamesystem.so"
2017-06-12 11:51:14.349 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/managers/system_manager.so: is missing DT_SONAME will use basename as a replacement: "system_manager.so"
2017-06-12 11:51:14.350 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/entity.so: is missing DT_SONAME will use basename as a replacement: "entity.so"
2017-06-12 11:51:14.351 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/managers/sound_manager.so: is missing DT_SONAME will use basename as a replacement: "sound_manager.so"
2017-06-12 11:51:14.354 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/core/audio/audio_sdl2.so: is missing DT_SONAME will use basename as a replacement: "audio_sdl2.so"
2017-06-12 11:51:14.356 INFO:   python : [INFO   ] [Audio       ] Providers: audio_sdl2 (audio_ffpyplayer ignored)
2017-06-12 11:51:14.357 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/gameworld.so: is missing DT_SONAME will use basename as a replacement: "gameworld.so"
2017-06-12 11:51:14.358 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/systems/position_systems.so: is missing DT_SONAME will use basename as a replacement: "position_systems.so"
2017-06-12 11:51:14.359 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/managers/animation_manager.so: is missing DT_SONAME will use basename as a replacement: "animation_manager.so"
2017-06-12 11:51:14.360 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/animation.so: is missing DT_SONAME will use basename as a replacement: "animation.so"
2017-06-12 11:51:14.362 INFO:   python : [INFO   ] KURWA6
2017-06-12 11:51:14.363 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/systems/scale_systems.so: is missing DT_SONAME will use basename as a replacement: "scale_systems.so"
2017-06-12 11:51:14.364 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/systems/gameview.so: is missing DT_SONAME will use basename as a replacement: "gameview.so"
2017-06-12 11:51:14.366 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/systems/rotate_systems.so: is missing DT_SONAME will use basename as a replacement: "rotate_systems.so"
2017-06-12 11:51:14.367 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/systems/color_systems.so: is missing DT_SONAME will use basename as a replacement: "color_systems.so"
2017-06-12 11:51:14.368 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/systems/gamemap.so: is missing DT_SONAME will use basename as a replacement: "gamemap.so"
2017-06-12 11:51:14.369 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/systems/renderers.so: is missing DT_SONAME will use basename as a replacement: "renderers.so"
2017-06-12 11:51:14.370 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/batching.so: is missing DT_SONAME will use basename as a replacement: "batching.so"
2017-06-12 11:51:14.372 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/systems/lifespan.so: is missing DT_SONAME will use basename as a replacement: "lifespan.so"
2017-06-12 11:51:14.373 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/systems/animation.so: is missing DT_SONAME will use basename as a replacement: "animation.so"
2017-06-12 11:51:14.376 INFO:   python : [DEBUG  ] [App         ] Loading kv <./yourappname.kv>
2017-06-12 11:51:14.398 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/core/text/text_layout.so: is missing DT_SONAME will use basename as a replacement: "text_layout.so"
2017-06-12 11:51:14.400 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/core/text/_text_sdl2.so: is missing DT_SONAME will use basename as a replacement: "_text_sdl2.so"
2017-06-12 11:51:14.402 INFO:   python : [INFO   ] [Text        ] Provider: sdl2
2017-06-12 11:51:14.407 WARN:   linker : /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/jnius/jnius.so: is missing DT_SONAME will use basename as a replacement: "jnius.so"
2017-06-12 11:51:14.704 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253961468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:14.704 INFO:   DEVICE MANAGER : {"id":"1497253961468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:14.706 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253961468","orientation":"PORTRAIT"}'
2017-06-12 11:51:14.736 INFO:   python : [DEBUG  ] [Resource    ] add </system/fonts> in path list
2017-06-12 11:51:14.738 INFO:   python : [DEBUG  ] [Resource    ] add </data/user/0/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/data/fonts> in path list
2017-06-12 11:51:14.750 INFO:   python : [INFO   ] [Shader      ] Read <poscolorshader.glsl>
2017-06-12 11:51:14.756 INFO:   python : [DEBUG  ] [Shader      ] Vertex compiled successfully
2017-06-12 11:51:14.760 INFO:   python : [DEBUG  ] [Shader      ] Fragment compiled successfully
2017-06-12 11:51:14.772 INFO:   python : [ERROR  ] [GameSystem  ] System_id: position not attached retrying in 1 sec. If you see this error once or twice, we are probably just waiting on the KV file to load. If you see it a whole bunch something is probably wrong. Make sure all systems are setup properly.
2017-06-12 11:51:14.774 INFO:   python : [DEBUG  ] [Base        ] Create provider from android
2017-06-12 11:51:14.774 INFO:   python : [WARNING] [Base        ] Unknown <android> provider
2017-06-12 11:51:14.775 INFO:   python : [INFO   ] [Base        ] Start application main loop
2017-06-12 11:51:14.780 INFO:   python : [INFO   ] [GL          ] NPOT texture support is available
2017-06-12 11:51:14.782 INFO:   python : [ERROR  ] [Base        ] Failed to import "android" module. Could not remove android presplash.
2017-06-12 11:51:14.784 INFO:   python : [DEBUG  ] [Atlas       ] Load </data/user/0/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/data/images/defaulttheme.atlas>
2017-06-12 11:51:14.789 INFO:   python : [DEBUG  ] [Atlas       ] Need to load 1 images
2017-06-12 11:51:14.790 INFO:   python : [DEBUG  ] [Atlas       ] Load </data/user/0/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/data/images/defaulttheme-0.png>
2017-06-12 11:51:14.791 INFO:   python : [DEBUG  ] [ImageSDL2   ] Load </data/user/0/org.test.myapp/files/app/lib/python2.7/site-packages/kivy/data/images/defaulttheme-0.png>
2017-06-12 11:51:14.917 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:14.931 INFO:   art : Explicit concurrent mark sweep GC freed 104(4KB) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 191us total 13.204ms
2017-06-12 11:51:15.203 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253961968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:15.203 INFO:   DEVICE MANAGER : {"id":"1497253961968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:15.204 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253961968","orientation":"PORTRAIT"}'
2017-06-12 11:51:15.704 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253962468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:15.704 INFO:   DEVICE MANAGER : {"id":"1497253962468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:15.706 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253962468","orientation":"PORTRAIT"}'
2017-06-12 11:51:16.206 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253962968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:16.206 INFO:   DEVICE MANAGER : {"id":"1497253962968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:16.210 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253962968","orientation":"PORTRAIT"}'
2017-06-12 11:51:16.419 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:16.475 INFO:   art : Explicit concurrent mark sweep GC freed 38(2112B) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 277us total 55.353ms
2017-06-12 11:51:16.706 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253963468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:16.706 INFO:   DEVICE MANAGER : {"id":"1497253963468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:16.709 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253963468","orientation":"PORTRAIT"}'
2017-06-12 11:51:17.187 INFO:   python : [INFO   ] [KivEnt      ] Vertex Format: vertex_format_4f4ub registered. Size per vertex is: 20. Format is [('pos', 2, 'float', 0, False), ('uvs', 2, 'float', 8, False), ('v_color', 4, 'ubyte', 16, True)].
2017-06-12 11:51:17.188 INFO:   python : [INFO   ] [KivEnt      ] Vertex Format: vertex_format_4f registered. Size per vertex is: 16. Format is [('pos', 2, 'float', 0, False), ('uvs', 2, 'float', 8, False)].
2017-06-12 11:51:17.188 INFO:   python : [INFO   ] [KivEnt      ] Vertex Format: vertex_format_2f4ub registered. Size per vertex is: 12. Format is [('pos', 2, 'float', 0, False), ('v_color', 4, 'ubyte', 8, True)].
2017-06-12 11:51:17.188 INFO:   python : [INFO   ] [KivEnt      ] Vertex Format: vertex_format_5f4ub registered. Size per vertex is: 24. Format is [('pos', 2, 'float', 0, False), ('rot', 1, 'float', 8, False), ('center', 2, 'float', 12, False), ('v_color', 4, 'ubyte', 20, True)].
2017-06-12 11:51:17.189 INFO:   python : [INFO   ] [KivEnt      ] Vertex Format: vertex_format_7f registered. Size per vertex is: 28. Format is [('pos', 2, 'float', 0, False), ('uvs', 2, 'float', 8, False), ('rot', 1, 'float', 16, False), ('center', 2, 'float', 20, False)].
2017-06-12 11:51:17.189 INFO:   python : [INFO   ] [KivEnt      ] Vertex Format: vertex_format_7f4ub registered. Size per vertex is: 32. Format is [('pos', 2, 'float', 0, False), ('uvs', 2, 'float', 8, False), ('rot', 1, 'float', 16, False), ('center', 2, 'float', 20, False), ('v_color', 4, 'ubyte', 28, True)].
2017-06-12 11:51:17.189 INFO:   python : [INFO   ] [KivEnt      ] Model Manager reserved space for vertex format: vertex_format_2f4ub. 200 KiB was reserved for vertices, fitting a total of 17066. 200 KiB was reserved for indices fitting a total of 102400.
2017-06-12 11:51:17.206 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253963968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:17.206 INFO:   DEVICE MANAGER : {"id":"1497253963968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:17.210 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253963968","orientation":"PORTRAIT"}'
2017-06-12 11:51:17.487 INFO:   python : [INFO   ] [KivEnt      ] position allocated 7680 KiB
2017-06-12 11:51:17.611 INFO:   art : Waiting for a blocking GC DisableMovingGc
2017-06-12 11:51:17.612 INFO:   art : Waiting for a blocking GC DisableMovingGc
2017-06-12 11:51:17.613 INFO:   art : Starting a blocking GC DisableMovingGc
2017-06-12 11:51:17.619 INFO:   art : WaitForGcToComplete blocked for 6.645ms for cause DisableMovingGc
2017-06-12 11:51:17.619 INFO:   art : Starting a blocking GC DisableMovingGc
2017-06-12 11:51:17.680 INFO:   PlaceInferenceEngine : [anon] Changed inference mode: 105
2017-06-12 11:51:17.703 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253964468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:17.703 INFO:   DEVICE MANAGER : {"id":"1497253964468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:17.705 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253964468","orientation":"PORTRAIT"}'
2017-06-12 11:51:17.831 INFO:   python : [INFO   ] [KivEnt      ] Batches for canvas: <kivy.graphics.instructions.RenderContext object at 0xcd707648> will have 21845 verts and 131072 indices.VBO will be 256 in KiB per frame with 20 total vbos, an estimated 5461 enities fit in each batch with 4 verts per entity
2017-06-12 11:51:17.832 INFO:   python : [INFO   ] [KivEnt      ] poly_renderer allocated 30304 KiB
2017-06-12 11:51:17.832 INFO:   python : [INFO   ] [KivEnt      ] We will need 60026 KiB for game, we have 614400 KiB
2017-06-12 11:51:17.834 INFO:   python : [DEBUG  ] in _batch_entity model._vertex_count=3 model._index_count=3
2017-06-12 11:51:17.834 INFO:   python : [DEBUG  ] vbo_size=256
2017-06-12 11:51:17.835 INFO:   python : [DEBUG  ] set index_vbo.data_size to 0
2017-06-12 11:51:17.835 INFO:   python : [DEBUG  ] batch add_entity num_indices=3 num_verts=3
2017-06-12 11:51:17.835 INFO:   python : [DEBUG  ] [KivEnt      ] Entity: 0 batched at vertex#: 0 indices#: 0
2017-06-12 11:51:17.835 INFO:   python : [DEBUG  ] [KivEnt      ] Entity 0 created with components: position: 0, poly_renderer: 0,
2017-06-12 11:51:17.841 INFO:   python : [DEBUG  ] self.current_frame=1 self.frame_count=1
2017-06-12 11:51:17.841 INFO:   python : [DEBUG  ] will bind vertices
2017-06-12 11:51:17.842 INFO:   python : [DEBUG  ] glBufferData(target=34962 data_size=262144L usage=35040) (will dump first 300)
2017-06-12 11:51:17.842 INFO:   python : 00000000: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.842 INFO:   python : 00000010: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.842 INFO:   python : 00000020: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.842 INFO:   python : 00000030: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.842 INFO:   python : 00000040: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.842 INFO:   python : 00000050: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.842 INFO:   python : 00000060: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.842 INFO:   python : 00000070: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.842 INFO:   python : 00000080: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.842 INFO:   python : 00000090: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.842 INFO:   python : 000000A0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.842 INFO:   python : 000000B0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.843 INFO:   python : 000000C0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.843 INFO:   python : 000000D0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.843 INFO:   python : 000000E0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.843 INFO:   python : 000000F0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.843 INFO:   python : 00000100: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.843 INFO:   python : 00000110: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:17.843 INFO:   python : 00000120: 00 00 00 00 00 00 00 00  00 00 00 00              ............
2017-06-12 11:51:17.844 INFO:   python : [DEBUG  ] glVertexAttribPointer(1, 2, 5126, 0, 12, 0)
2017-06-12 11:51:17.844 INFO:   python : [DEBUG  ] glVertexAttribPointer(0, 4, 5121, 1, 12, 8)
2017-06-12 11:51:17.844 INFO:   python : [DEBUG  ] ended bind vertices
2017-06-12 11:51:17.844 INFO:   python : [DEBUG  ] will bind indices
2017-06-12 11:51:17.845 INFO:   python : [DEBUG  ] glBufferSubData(target=34963 data_size=0L) (will dump first 300)
2017-06-12 11:51:17.845 INFO:   python : [DEBUG  ] ended bind indices
2017-06-12 11:51:17.845 INFO:   python : [INFO   ] glDrawElements(mode=4 indices.data_size=0)
2017-06-12 11:51:17.922 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:17.946 INFO:   art : Explicit concurrent mark sweep GC freed 38(2112B) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 180us total 23.590ms
2017-06-12 11:51:18.204 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253964968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:18.204 INFO:   DEVICE MANAGER : {"id":"1497253964968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:18.205 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253964968","orientation":"PORTRAIT"}'
2017-06-12 11:51:18.347 INFO:   python : [INFO   ] after glDrawElements
2017-06-12 11:51:18.348 INFO:   python : [INFO   ] after vertices undbind
2017-06-12 11:51:18.348 INFO:   python : [INFO   ] after indices unbind
2017-06-12 11:51:18.362 INFO:   python : [DEBUG  ] Renderer.update for batch_key=4294967295
2017-06-12 11:51:18.363 INFO:   python : [DEBUG  ] batches = [<kivent_core.rendering.batching.IndexedBatch object at 0xc5531130>]
2017-06-12 11:51:18.364 INFO:   python : [DEBUG  ] for batch = <kivent_core.rendering.batching.IndexedBatch object at 0xc5531130>, static_rendering=False force_update=False
2017-06-12 11:51:18.365 INFO:   python : [DEBUG  ] set_index_count_for_frame(index_count=3)
2017-06-12 11:51:18.371 INFO:   python : [DEBUG  ] self.current_frame=2 self.frame_count=1
2017-06-12 11:51:18.372 INFO:   python : [DEBUG  ] will bind vertices
2017-06-12 11:51:18.372 INFO:   python : [DEBUG  ] glBufferSubData(target=34962 data_size=262144L) (will dump first 300)
2017-06-12 11:51:18.373 INFO:   python : 00000000: 00 00 C8 41 00 00 C8 41  FF 00 00 FF 00 00 2F 43  ...A...A....../C
2017-06-12 11:51:18.373 INFO:   python : 00000010: 00 00 C8 41 00 FF 00 FF  00 00 C8 42 00 00 2F 43  ...A.......B../C
2017-06-12 11:51:18.373 INFO:   python : 00000020: 00 00 FF FF 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.373 INFO:   python : 00000030: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.373 INFO:   python : 00000040: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.374 INFO:   python : 00000050: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.374 INFO:   python : 00000060: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.374 INFO:   python : 00000070: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.374 INFO:   python : 00000080: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.374 INFO:   python : 00000090: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.374 INFO:   python : 000000A0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.374 INFO:   python : 000000B0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.375 INFO:   python : 000000C0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.375 INFO:   python : 000000D0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.375 INFO:   python : 000000E0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.375 INFO:   python : 000000F0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.375 INFO:   python : 00000100: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.375 INFO:   python : 00000110: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ................
2017-06-12 11:51:18.375 INFO:   python : 00000120: 00 00 00 00 00 00 00 00  00 00 00 00              ............
2017-06-12 11:51:18.376 INFO:   python : [DEBUG  ] glVertexAttribPointer(1, 2, 5126, 0, 12, 0)
2017-06-12 11:51:18.377 INFO:   python : [DEBUG  ] glVertexAttribPointer(0, 4, 5121, 1, 12, 8)
2017-06-12 11:51:18.377 INFO:   python : [DEBUG  ] ended bind vertices
2017-06-12 11:51:18.377 INFO:   python : [DEBUG  ] will bind indices
2017-06-12 11:51:18.378 INFO:   python : [DEBUG  ] glBufferData(target=34963 data_size=6L usage=35040) (will dump first 300)
2017-06-12 11:51:18.378 INFO:   python : 00000000: 00 00 01 00 02 00                                 ......
2017-06-12 11:51:18.379 INFO:   python : [DEBUG  ] ended bind indices
2017-06-12 11:51:18.379 INFO:   python : [INFO   ] glDrawElements(mode=4 indices.data_size=6)
2017-06-12 11:51:18.379 INFO:   python : --------- beginning of crash
2017-06-12 11:51:18.380 ASSERT: libc : Fatal signal 11 (SIGSEGV), code 1, fault addr 0x34 in tid 9579 (SDLThread)
2017-06-12 11:51:18.394 WARN:    : debuggerd: handling request: pid=9536 uid=10132 gid=10132 tid=9579
2017-06-12 11:51:18.407 WARN:   debuggerd : type=1400 audit(0.0:68): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:69): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:70): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:71): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:72): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:73): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:74): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:75): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:76): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:77): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:78): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:79): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:80): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:81): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.411 WARN:   debuggerd : type=1400 audit(0.0:82): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.414 WARN:   debuggerd : type=1400 audit(0.0:83): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.414 WARN:   debuggerd : type=1400 audit(0.0:84): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.414 WARN:   debuggerd : type=1400 audit(0.0:85): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.414 WARN:   debuggerd : type=1400 audit(0.0:86): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.414 WARN:   debuggerd : type=1400 audit(0.0:87): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.414 WARN:   debuggerd : type=1400 audit(0.0:88): avc: denied { search } for name="org.test.myapp" dev="dm-2" ino=1504592 scontext=u:r:debuggerd:s0 tcontext=u:object_r:app_data_file:s0:c512,c768 tclass=dir permissive=0
2017-06-12 11:51:18.497 ASSERT: DEBUG : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
2017-06-12 11:51:18.497 ASSERT: DEBUG : Build fingerprint: 'google/bullhead/bullhead:7.1.2/N2G47O/3852959:user/release-keys'
2017-06-12 11:51:18.497 ASSERT: DEBUG : Revision: 'rev_1.0'
2017-06-12 11:51:18.497 ASSERT: DEBUG : ABI: 'arm'
2017-06-12 11:51:18.498 ASSERT: DEBUG : pid: 9536, tid: 9579, name: SDLThread  >>> org.test.myapp <<<
2017-06-12 11:51:18.498 ASSERT: DEBUG : signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x34
2017-06-12 11:51:18.498 ASSERT: DEBUG : r0 cdfda254  r1 00000000  r2 ce2c9e80  r3 dc22120c
2017-06-12 11:51:18.498 ASSERT: DEBUG : r4 ce2c9ed4  r5 00008be7  r6 00000001  r7 00000060
2017-06-12 11:51:18.498 ASSERT: DEBUG : r8 ce2f12c0  r9 ce2c9ed4  sl 00000000  fp 00000000
2017-06-12 11:51:18.498 ASSERT: DEBUG : ip 00000000  sp cfec5d78  lr dc1131ff  pc dc113204  cpsr 800f0030
2017-06-12 11:51:18.503 ASSERT: DEBUG : backtrace:
2017-06-12 11:51:18.504 ASSERT: DEBUG : #00 pc 000d3204  /vendor/lib/egl/libGLESv2_adreno.so
2017-06-12 11:51:18.504 ASSERT: DEBUG : #01 pc 000d79bb  /vendor/lib/egl/libGLESv2_adreno.so (_ZN21EsxGlApiParamValidate14GlDrawElementsEP11EsxDispatchjijPKv+122)
2017-06-12 11:51:18.504 ASSERT: DEBUG : #02 pc 00096f83  /vendor/lib/egl/libGLESv2_adreno.so (glDrawElements+34)
2017-06-12 11:51:18.504 ASSERT: DEBUG : #03 pc 0000828b  /data/data/org.test.myapp/files/app/lib/python2.7/site-packages/kivent_core/rendering/batching.so
2017-06-12 11:51:18.704 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253965468","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:18.705 INFO:   DEVICE MANAGER : {"id":"1497253965468","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:18.707 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253965468","orientation":"PORTRAIT"}'
2017-06-12 11:51:19.204 INFO:   TOOLKIT SERVICE : Request body '{"id":"1497253965968","type":"GET_SCREEN_ORIENTATION"}'
2017-06-12 11:51:19.205 INFO:   DEVICE MANAGER : {"id":"1497253965968","type":"GET_SCREEN_ORIENTATION"}
2017-06-12 11:51:19.207 INFO:   TOOLKIT SERVICE : Responding to client with: '{"id":"1497253965968","orientation":"PORTRAIT"}'
2017-06-12 11:51:19.426 INFO:   art : Starting a blocking GC Explicit
2017-06-12 11:51:19.455 INFO:   art : Explicit concurrent mark sweep GC freed 38(2112B) AllocSpace objects, 0(0B) LOS objects, 40% free, 18MB/30MB, paused 311us total 27.896ms
2017-06-12 11:51:19.594 WARN:   ActivityManager : Force finishing activity org.test.myapp/org.kivy.android.PythonActivity
2017-06-12 11:51:19.607 WARN:    : debuggerd: resuming target 9536
2017-06-12 11:51:19.609 INFO:   BootReceiver : Copying /data/tombstones/tombstone_01 to DropBox (SYSTEM_TOMBSTONE)
2017-06-12 11:51:19.615 ERROR:  lowmemorykiller : Error writing /proc/9536/oom_score_adj; errno=22
2017-06-12 11:51:19.616 WARN:   ActivityManager : Failed setting process group of 9536 to 1
2017-06-12 11:51:19.616 WARN:   System.err : java.lang.IllegalArgumentException: Given thread 9565 does not exist
2017-06-12 11:51:19.616 WARN:   System.err : at android.os.Process.setThreadPriority(Native Method)
2017-06-12 11:51:19.616 WARN:   System.err : at com.android.server.am.ActivityManagerService.applyOomAdjLocked(ActivityManagerService.java:20546)
2017-06-12 11:51:19.616 WARN:   System.err : at com.android.server.am.ActivityManagerService.updateOomAdjLocked(ActivityManagerService.java:21048)
2017-06-12 11:51:19.616 WARN:   System.err : at com.android.server.am.BroadcastQueue.processCurBroadcastLocked(BroadcastQueue.java:274)
2017-06-12 11:51:19.616 WARN:   System.err : at com.android.server.am.BroadcastQueue.processNextBroadcast(BroadcastQueue.java:1225)
2017-06-12 11:51:19.616 WARN:   System.err : at com.android.server.am.BroadcastQueue$BroadcastHandler.handleMessage(BroadcastQueue.java:172)
2017-06-12 11:51:19.616 WARN:   System.err : at android.os.Handler.dispatchMessage(Handler.java:102)
2017-06-12 11:51:19.616 WARN:   System.err : at android.os.Looper.loop(Looper.java:154)
2017-06-12 11:51:19.616 WARN:   System.err : at android.os.HandlerThread.run(HandlerThread.java:61)
2017-06-12 11:51:19.616 WARN:   System.err : at com.android.server.ServiceThread.run(ServiceThread.java:46)
2017-06-12 11:51:19.663 INFO:   OpenGLRenderer : Initialized EGL, version 1.4
2017-06-12 11:51:19.663 DEBUG:  OpenGLRenderer : Swap behavior 1
2017-06-12 11:51:19.674 INFO:   WindowManager : WIN DEATH: Window{2fcb3e1 u0 SurfaceView - org.test.myapp/org.kivy.android.PythonActivity}
2017-06-12 11:51:19.675 DEBUG:  GraphicsStats : Buffer count: 3
2017-06-12 11:51:19.675 INFO:   sensors : activate
2017-06-12 11:51:19.675 INFO:   ActivityManager : Process org.test.myapp (pid 9536) has died
2017-06-12 11:51:19.675 DEBUG:  ActivityManager : cleanUpApplicationRecord -- 9536
2017-06-12 11:51:19.677 INFO:   nanohub : queueActivate: sensor=1, handle=1, enable=0
2017-06-12 11:51:19.679 INFO:   nanohub : osLog: [BMI160] accSetRate: rate=51200, latency=-256, state=3
2017-06-12 11:51:19.681 INFO:   Zygote : Process 9536 exited due to signal (11)
2017-06-12 11:51:19.691 WARN:   InputDispatcher : channel '1a08ca0 org.test.myapp/org.kivy.android.PythonActivity (server)' ~ Consumer closed input channel or an error occurred.  events=0x9
2017-06-12 11:51:19.691 ERROR:  InputDispatcher : channel '1a08ca0 org.test.myapp/org.kivy.android.PythonActivity (server)' ~ Channel is unrecoverably broken and will be disposed!
2017-06-12 11:51:19.692 INFO:   WindowManager : WIN DEATH: Window{1a08ca0 u0 org.test.myapp/org.kivy.android.PythonActivity}
2017-06-12 11:51:19.692 WARN:   InputDispatcher : Attempted to unregister already unregistered input channel '1a08ca0 org.test.myapp/org.kivy.android.PythonActivity (server)'

[maho]

I have idea that I could write testcase of bug in adreno drivers in pure opengl. To be able to report to them or (more likely) search for workaround.

Could someone show me simple example of android app (python for android or just java android) like "draw triangle in opengl"?