771626 - tegras seem to be rebooting or remounting sdcard mid test

Status: RESOLVED FIXED

(Testing :: General, defect)

Description

[Joel Maher ( :jmaher ) (UTC -8)]

in looking at some log files, our tests stop midway through with no error.  The resulting logcat that shows up is a bootup sequence.

Comment 1

[Mike Taylor [:bear]]

can you give us a set of tegras and date/times?  Callek or myself can then get the foopy side logs and try to figure out if they are being rebooted/stopped or what

Comment 2

[Joel Maher ( :jmaher ) (UTC -8)]

tegra-154 (July 5, 2012 12:15-12:45PDT)
tegra-224 (July 5, 2012 12:15-12:30PDT)

Comment 3

[Mike Taylor [:bear]]

tegra-154 has the following repeated:

2012-07-05 12:16:33,597 INFO    MainProcess: heartbeat detected
2012-07-05 12:16:33,598 WARNING MainProcess: Tegra active but error flag set [5/5]
2012-07-05 12:16:33,598 WARNING MainProcess: hard reset reboot check [75/3]
2012-07-05 12:16:33,614 INFO    MainProcess: heartbeat detected
2012-07-05 12:17:33,735 INFO    MainProcess: heartbeat detected

the last error.flg shows:

Device manager lost connection to tegra

The logs don't show any signs of reboots or restarts.

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

well the logcat output in the test looks to be from a fresh reboot.  It normally has data related to loading pages and other related output.

Comment 5

[Joel Maher ( :jmaher ) (UTC -8)]

2 tests from m-c this morning.  Both m2 runs.  Here is what I see in the log (both are similar):
Error receiving data from socket. cmd=ps
; err=[Errno 54] Connection reset by peer
reconnecting socket
17844 INFO TEST-PASS | /tests/content/media/test/test_bug495145.html | Playing after pause while ended works for seek.webm#1
17845 INFO TEST-PASS | /tests/content/media/test/test_bug495145.html | [finished seek.webm-3a] Length of array should match number of running tests - 1 should equal 1
17846 INFO TEST-PASS | /tests/content/media/test/test_bug495145.html | Playing after pause while ended works for detodos.opus#1
17847 INFO TEST-PASS | /tests/content/media/test/test_bug495145.html | [finished detodos.opus-4a] Length of array should match number of running tests - 0 should equal 0
INFO | automation.py | Application ran for: 0:07:31.080939
INFO | automation.py | Reading PID log: /tmp/tmpQ1BOZ7pidlog
getting files in '/mnt/sdcard/tests/profile/minidumps/'

What happens is the logcat information after this is a reboot instead of test related data.  I did double check that other green runs from this changeset show test data in the logcat output.

Here are the two logs:
https://tbpl.mozilla.org/php/getParsedLog.php?id=13386515&tree=Firefox&full=1 (tegra-058)
https://tbpl.mozilla.org/php/getParsedLog.php?id=13388303&tree=Firefox&full=1 (tegra-038)

Comment 6

[Joel Maher ( :jmaher ) (UTC -8)]

and reftest-2 on tegra-083 has a similar pattern in the log file:
https://tbpl.mozilla.org/php/getParsedLog.php?id=13387078&tree=Firefox&full=1

Error receiving data from socket. cmd=ps
; err=[Errno 54] Connection reset by peer
reconnecting socket
RESTORE PREFERENCE pref(font.size.inflation.emPerLine,0)
RESTORE PREFERENCE pref(font.size.inflation.lineThreshold,400)
REFTEST TEST-START | http://10.250.48.211:30083/tests/layout/reftests/font-inflation/relevant-width-overflow-1-ref.html | 1508 / 2683 (56%)
REFTEST TEST-PASS | http://10.250.48.211:30083/tests/layout/reftests/font-inflation/relevant-width-overflow-1.html | image comparison (==) 
REFTEST INFO | Loading a blank page
SET PREFERENCE pref(font.size.inflation.emPerLine,15)
SET PREFERENCE pref(font.size.inflation.lineThreshold,0)
REFTEST TEST-START | http://10.250.48.211:30083/tests/layout/reftests/font-inflation/min-width-passes-1.html | 1509 / 2683 (56%)
INFO | automation.py | Application ran for: 0:19:26.077624
INFO | automation.py | Reading PID log: /tmp/tmppdo2EHpidlog

Comment 7

[Mike Taylor [:bear]]

Attachment: add a shared reboot log for tegras per foopy

Comment 8

[Justin Wood (:Callek)]

Attachment: Do logging everywhere

Armen, can you also be sure to review my pastebin of a devicemanagerSUT.py change to use this.

http://callek.pastebin.mozilla.org/1708595  (if devicemanager balks in real jobs we can backout this part, but afaik this copy of devicemanagerSUT is *only* used for the foopy/sut_tools magic we have)

Comment 9

[Armen [:armenzg]]

The pastebin looks good too.

Comment 10

[Justin Wood (:Callek)]

So I checked that in with 

http://hg.mozilla.org/build/tools/rev/2e38c0d51e81

Then after gracefulling all masters I did (allowing us to have an easy out from the devicemanagerSUT change)

scp [e-mail]:/builds/sut_tools/devicemanagerSUT.py sut_tools/devicemanagerSUT.py.new ; ./stop_cp.sh; hg -R tools pull -u; mv sut_tools/devicemanagerSUT.py{,.old}; mv sut_tools/devicemanagerSUT.py{.new,}

Then I got the masters restarted and did a ./start_cp.sh on all foopies.

After all that was done, I noticed (and told tree-sheriff) that we were busted in tree. So landed followups

http://hg.mozilla.org/build/tools/rev/e83b225cfc83
http://hg.mozilla.org/build/tools/rev/c23c755c5971

And did a stop_cp across all machine at the same time as the graceful (in order to help get machines in a good state faster, even though it has short-term bustage from doing that).

after which I did a new hg -R tools pull -u and restarted cp/masters

Comment 11

[Justin Wood (:Callek)]

A single instance:

========= Started get_buildername (results: 0, elapsed: 0 secs) (at 2012-07-20 05:14:53.550514) =========
Building on: tegra-183

....

========= Finished Reboot Device (results: 0, elapsed: 12 mins, 31 secs) (at 2012-07-20 06:05:37.622740) =========


Had a bunch of reboot attempts:

2012-07-20 05:17:56,515 10.250.50.93    MainProcess: Reboot Tegra Called for tegra 10.250.50.93
2012-07-20 05:17:56,578 10.250.50.93    MainProcess:   File "/builds/sut_tools/installApp.py", line 190, in <module>
2012-07-20 05:17:56,578 10.250.50.93    MainProcess:     main(sys.argv)
2012-07-20 05:17:56,578 10.250.50.93    MainProcess:
2012-07-20 05:17:56,579 10.250.50.93    MainProcess:   File "/builds/sut_tools/installApp.py", line 175, in main
2012-07-20 05:17:56,579 10.250.50.93    MainProcess:     dm, devRoot = one_time_setup(ip_addr, path_to_main_apk)
2012-07-20 05:17:56,579 10.250.50.93    MainProcess:
2012-07-20 05:17:56,580 10.250.50.93    MainProcess:   File "/builds/sut_tools/installApp.py", line 148, in one_time_setup
2012-07-20 05:17:56,580 10.250.50.93    MainProcess:     dm.reboot(proxyIP, proxyPort)
2012-07-20 05:17:56,580 10.250.50.93    MainProcess:
2012-07-20 05:17:56,580 10.250.50.93    MainProcess:   File "/builds/tools/sut_tools/devicemanagerSUT.py", line 907, in reboot
2012-07-20 05:17:56,581 10.250.50.93    MainProcess:     logRebootTraceback(self.host)
2012-07-20 05:17:56,581 10.250.50.93    MainProcess:
2012-07-20 05:17:56,581 10.250.50.93    MainProcess:   File "/builds/tools/sut_tools/sut_lib.py", line 252, in logRebootTraceback
2012-07-20 05:17:56,581 10.250.50.93    MainProcess:     for s in traceback.format_list(traceback.extract_stack()):
2012-07-20 05:17:56,581 10.250.50.93    MainProcess:
2012-07-20 05:29:19,680 10.250.50.93    MainProcess: process shutting down
2012-07-20 05:29:19,680 10.250.50.93    MainProcess: running all "atexit" finalizers with priority >= 0
2012-07-20 05:29:19,680 10.250.50.93    MainProcess: running the remaining "atexit" finalizers
2012-07-20 05:29:51,223 10.250.50.93    MainProcess: Reboot Tegra Called for tegra 10.250.50.93
2012-07-20 05:29:51,225 10.250.50.93    MainProcess:   File "/builds/sut_tools/config.py", line 113, in <module>
2012-07-20 05:29:51,225 10.250.50.93    MainProcess:     status = dm.reboot(ipAddr=proxyIP, port=proxyPort)
2012-07-20 05:29:51,225 10.250.50.93    MainProcess:
2012-07-20 05:29:51,225 10.250.50.93    MainProcess:   File "/builds/tools/sut_tools/devicemanagerSUT.py", line 907, in reboot
2012-07-20 05:29:51,225 10.250.50.93    MainProcess:     logRebootTraceback(self.host)
2012-07-20 05:29:51,225 10.250.50.93    MainProcess:
2012-07-20 05:29:51,226 10.250.50.93    MainProcess:   File "/builds/tools/sut_tools/sut_lib.py", line 252, in logRebootTraceback
2012-07-20 05:29:51,226 10.250.50.93    MainProcess:     for s in traceback.format_list(traceback.extract_stack()):
2012-07-20 05:29:51,226 10.250.50.93    MainProcess:
2012-07-20 05:32:51,564 10.250.50.93    MainProcess: process shutting down
2012-07-20 05:32:51,565 10.250.50.93    MainProcess: running all "atexit" finalizers with priority >= 0
2012-07-20 05:32:51,565 10.250.50.93    MainProcess: running the remaining "atexit" finalizers
2012-07-20 05:53:36,999 10.250.50.93    MainProcess: Reboot Tegra Called for tegra 10.250.50.93
2012-07-20 05:53:37,000 10.250.50.93    MainProcess:   File "/builds/sut_tools/reboot.py", line 32, in <module>
2012-07-20 05:53:37,000 10.250.50.93    MainProcess:     status = dm.reboot(ipAddr=proxyIP, port=proxyPort)
2012-07-20 05:53:37,000 10.250.50.93    MainProcess:
2012-07-20 05:53:37,000 10.250.50.93    MainProcess:   File "/builds/tools/sut_tools/devicemanagerSUT.py", line 907, in reboot
2012-07-20 05:53:37,001 10.250.50.93    MainProcess:     logRebootTraceback(self.host)
2012-07-20 05:53:37,001 10.250.50.93    MainProcess:
2012-07-20 05:53:37,001 10.250.50.93    MainProcess:   File "/builds/tools/sut_tools/sut_lib.py", line 252, in logRebootTraceback
2012-07-20 05:53:37,001 10.250.50.93    MainProcess:     for s in traceback.format_list(traceback.extract_stack()):
2012-07-20 05:53:37,001 10.250.50.93    MainProcess:
2012-07-20 06:05:37,480 10.250.50.93    MainProcess: process shutting down
2012-07-20 06:05:37,481 10.250.50.93    MainProcess: running all "atexit" finalizers with priority >= 0
2012-07-20 06:05:37,481 10.250.50.93    MainProcess: running the remaining "atexit" finalizers

I'm still checking a few others that Joel handed me, but this is for starters

Comment 12

[Justin Wood (:Callek)]

Ok, another single instance. This one is tegra-317 (a new tegra from our new batch)

It has the new (1.11) SUTAgent, but not the new watcher.ini

A jsreftest job:
...
Automation error: Error receiving data from socket (possible reboot). cmd={'cmd': 'ps'}; err=[Errno 54] Connection reset by peer
...


REFTEST INFO | runreftest.py | Running tests: end.
--------- beginning of /dev/log/main
I/DEBUG   (  943): debuggerd: Feb  2 2011 10:46:35
D/dhcpcd  (  954): dhcpcd 4.0.15 starting
--------- beginning of /dev/log/system
I/Vold    (  941): Vold 2.1 (the revenge) firing up
I/Netd    (  942): Netd 1.0 starting
D/Vold    (  941): Volume sdcard state changing -1 (Initializing) -> 0 (No-Media)
D/Vold    (  941): Volume usbdisk state changing -1 (Initializing) -> 0 (No-Media)
W/logwrapper(  983): Unable to background process (No such file or directory)
D/Vold    (  941): Volume sdcard state changing 0 (No-Media) -> 1 (Idle-Unmounted)
W/Vold    (  941): Duplicate state (1)
I/Vold    (  941): /dev/block/vold/179:9 being considered for volume sdcard
D/Vold    (  941): Volume sdcard state changing 1 (Idle-Unmounted) -> 3 (Checking)
I//system/bin/fsck_msdos(  941): ** /dev/block/vold/179:9
I//system/bin/fsck_msdos(  941): ** Phase 1 - Read and Compare FATs
I//system/bin/fsck_msdos(  941): Attempting to allocate 1898 KB for FAT
I//system/bin/fsck_msdos(  941): Attempting to allocate 1898 KB for FAT
D/dhcpcd  (  954): hardware address = 02:04:4b:00:cf:6d
D/dhcpcd  (  954): executing `/system/etc/dhcpcd/dhcpcd-run-hooks', reason PREINIT
D/dhcpcd  (  954): host does not support a monotonic clock - timing can skew
D/dhcpcd  (  954): broadcasting for a lease
D/dhcpcd  (  954): sending DHCP_DISCOVER with xid 0xd7d8c8c9, next in 4.59 seconds
I//system/bin/fsck_msdos(  941): ** Phase 2 - Check Cluster Chains
I//system/bin/fsck_msdos(  941): ** Phase 3 - Checking Directories
I//system/bin/fsck_msdos(  941): ** Phase 4 - Checking for Lost Files
I//system/bin/fsck_msdos(  941): Lost cluster chain at cluster 1035
I//system/bin/fsck_msdos(  941): 1 Cluster(s) lost
I//system/bin/fsck_msdos(  941): FIXED
I//system/bin/fsck_msdos(  941): Next free cluster in FSInfo block (1035) not free
I//system/bin/fsck_msdos(  941): FIXED
I//system/bin/fsck_msdos(  941): 87 files, 2943904 free (485213 clusters)
I//system/bin/fsck_msdos(  941): ***** FILE SYSTEM WAS MODIFIED *****
I/logwrapper(  941): /system/bin/fsck_msdos terminated by exit(4)
W/Vold    (  941): Filesystem modified - rechecking (pass 2)
I/Vold    (  941): Device /dev/block/vold/179:9, target /mnt/sdcard mounted @ /mnt/secure/staging
D/Vold    (  941): Volume sdcard state changing 3 (Checking) -> 4 (Mounted)
D/AndroidRuntime(  945): 
D/AndroidRuntime(  945): >>>>>>>>>>>>>> AndroidRuntime START <<<<<<<<<<<<<<
D/AndroidRuntime(  945): CheckJNI is ON
I/        (  946): ServiceManager: 0xace0
D/AndroidRuntime(  945): --- registering native functions ---
D/dhcpcd  (  954): carrier lost
D/AudioHardwareInterface(  946): setMode(NORMAL)
I/CameraService(  946): CameraService started: pid=946
I/SamplingProfilerIntegration(  945): Profiler is disabled.
I/AudioFlinger(  946): AudioFlinger's thread 0xbc08 ready to run
D/        (  953): NVRM_DAEMON(808): rt_exist=1, add client ref
I/Zygote  (  945): Preloading classes...
E/Zygote  (  945): setreuid() failed. errno: 30
I/bluetooth_ScoSocket.cpp(  945): Entry name = MY-CAR ScoTypes = 0x7f
I/bluetooth_ScoSocket.cpp(  945): Entry name = Motorola HF850 ScoTypes = 0x7
D/dhcpcd  (  954): carrier acquired
D/dhcpcd  (  954): broadcasting for a lease
D/dhcpcd  (  954): sending DHCP_DISCOVER with xid 0xf200d944, next in 4.33 seconds
I/Zygote  (  945): ...preloaded 1265 classes in 2188ms.
E/Zygote  (  945): setreuid() failed. errno: 30
I/Zygote  (  945): Preloading resources...
W/Zygote  (  945): Preloaded drawable resource #0x1080093 (res/drawable-mdpi/sym_def_app_icon.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080002 (res/drawable-mdpi/arrow_down_float.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10800b3 (res/drawable/btn_check.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10800b6 (res/drawable-mdpi/btn_check_label_background.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10800b7 (res/drawable-mdpi/btn_check_off.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10800bc (res/drawable-mdpi/btn_check_on.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080004 (res/drawable/btn_default.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080005 (res/drawable/btn_default_small.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080006 (res/drawable/btn_dropdown.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080008 (res/drawable/btn_plus.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080007 (res/drawable/btn_minus.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080009 (res/drawable/btn_radio.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108000a (res/drawable/btn_star.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080131 (res/drawable/btn_toggle.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080194 (res/drawable-mdpi/ic_emergency.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080012 (res/drawable-mdpi/divider_horizontal_bright.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080014 (res/drawable-mdpi/divider_horizontal_dark.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080016 (res/drawable/edit_text.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108016d (res/drawable/expander_group.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080062 (res/drawable/list_selector_background.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080227 (res/drawable-mdpi/menu_background.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080228 (res/drawable-mdpi/menu_background_fill_parent_width.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080229 (res/drawable/menu_selector.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080242 (res/drawable-mdpi/panel_background.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080249 (res/drawable-mdpi/popup_bottom_bright.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108024a (res/drawable-mdpi/popup_bottom_dark.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108024b (res/drawable-mdpi/popup_bottom_medium.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108024c (res/drawable-mdpi/popup_center_bright.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108024d (res/drawable-mdpi/popup_center_dark.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080250 (res/drawable-mdpi/popup_full_dark.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080253 (res/drawable-mdpi/popup_top_bright.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080254 (res/drawable-mdpi/popup_top_dark.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108006d (res/drawable/progress_indeterminate_horizontal.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108025a (res/drawable/progress_small.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108025b (res/drawable/progress_small_titlebar.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108027e (res/drawable-mdpi/scrollbar_handle_horizontal.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108027f (res/drawable-mdpi/scrollbar_handle_vertical.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080071 (res/drawable/spinner_dropdown_background.xml) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080362 (res/drawable-mdpi/title_bar_shadow.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10801d6 (res/drawable-mdpi/indicator_code_lock_drag_direction_green_up.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10801d7 (res/drawable-mdpi/indicator_code_lock_drag_direction_red_up.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10801d8 (res/drawable-mdpi/indicator_code_lock_point_area_default.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10801d9 (res/drawable-mdpi/indicator_code_lock_point_area_green.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10801da (res/drawable-mdpi/indicator_code_lock_point_area_red.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10801e8 (res/drawable-mdpi/jog_tab_bar_left_end_confirm_gray.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10801ec (res/drawable-mdpi/jog_tab_bar_left_end_normal.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10801ed (res/drawable-mdpi/jog_tab_bar_left_end_pressed.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10801f1 (res/drawable-mdpi/jog_tab_bar_right_end_confirm_gray.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10801f5 (res/drawable-mdpi/jog_tab_bar_right_end_normal.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10801f6 (res/drawable-mdpi/jog_tab_bar_right_end_pressed.9.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x10801fb (res/drawable-mdpi/jog_tab_left_confirm_gray.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080200 (res/drawable-mdpi/jog_tab_left_normal.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080201 (res/drawable-mdpi/jog_tab_left_pressed.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080203 (res/drawable-mdpi/jog_tab_right_confirm_gray.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x1080209 (res/drawable-mdpi/jog_tab_right_normal.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108020a (res/drawable-mdpi/jog_tab_right_pressed.png) that varies with configuration!!
W/Zygote  (  945): Preloaded drawable resource #0x108020d (res/drawable-mdpi/jog_tab_target_gray.png) that varies with configuration!!
I/Zygote  (  945): ...preloaded 61 resources in 134ms.
I/Zygote  (  945): ...preloaded 15 resources in 3ms.
I/Zygote  (  945): Accepting command socket connections
E/BatteryService( 1026): usbOnlinePath not found
I/sysproc ( 1026): Entered system_init()
I/sysproc ( 1026): ServiceManager: 0x131c10
I/SurfaceFlinger( 1026): SurfaceFlinger is starting
I/SurfaceFlinger( 1026): SurfaceFlinger's main thread ready to run. Initializing graphics H/W...
D/        ( 1026): NvGrFbDevOpen: Opened fb0 on disp 0 size 1024x768 format 1 rate 85.000000
D/libEGL  ( 1026): loaded /system/lib/egl/libGLES_android.so
D/libEGL  ( 1026): loaded /system/lib/egl/libEGL_tegra.so
D/libEGL  ( 1026): loaded /system/lib/egl/libGLESv1_CM_tegra.so
D/libEGL  ( 1026): loaded /system/lib/egl/libGLESv2_tegra.so
I/SurfaceFlinger( 1026): EGL informations:
I/SurfaceFlinger( 1026): # of configs : 56
I/SurfaceFlinger( 1026): vendor    : Android
I/SurfaceFlinger( 1026): version   : 1.4 Android META-EGL
I/SurfaceFlinger( 1026): extensions: EGL_KHR_image EGL_KHR_image_base EGL_KHR_image_pixmap EGL_KHR_gl_texture_2D_image EGL_KHR_gl_texture_cubemap_image EGL_KHR_gl_renderbuffer_image EGL_ANDROID_image_native_buffer EGL_ANDROID_swap_rectangle EGL_ANDROID_get_render_buffer 
I/SurfaceFlinger( 1026): Client API: OpenGL ES
I/SurfaceFlinger( 1026): EGLSurface: 8-8-8-8, config=0x3
E/libEGL  ( 1026): eglSetSwapRectangleANDROID:1861 error 3008 (EGL_BAD_DISPLAY)
I/SurfaceFlinger( 1026): flags     : 00100000
W/SurfaceFlinger( 1026): ro.sf.lcd_density not defined, using 160 dpi by default.
I/SurfaceFlinger( 1026): OpenGL informations:
I/SurfaceFlinger( 1026): vendor    : NVIDIA Corporation
I/SurfaceFlinger( 1026): renderer  : NVIDIA AP
I/SurfaceFlinger( 1026): version   : OpenGL ES-CM 1.1
I/SurfaceFlinger( 1026): extensions: GL_OES_byte_coordinates GL_OES_fixed_point GL_OES_single_precision GL_OES_read_format GL_OES_query_matrix GL_OES_compressed_paletted_texture GL_OES_matrix_palette GL_OES_extended_matrix_palette GL_OES_point_sprite GL_OES_point_size_array GL_OES_draw_texture GL_OES_matrix_get GL_OES_compressed_ETC1_RGB8_texture GL_OES_texture_cube_map GL_OES_framebuffer_object GL_OES_fbo_render_mipmap GL_OES_stencil8 GL_OES_rgb8_rgba8 GL_OES_vertex_half_float GL_OES_EGL_image GL_EXT_texture_compression_dxt1 GL_EXT_texture_compression_s3tc GL_EXT_bgra GL_EXT_texture_format_BGRA8888 GL_ARB_texture_non_power_of_two
I/SurfaceFlinger( 1026): GL_MAX_TEXTURE_SIZE = 3839
I/SurfaceFlinger( 1026): GL_MAX_VIEWPORT_DIMS = 3839
I/sysproc ( 1026): System server: starting Android runtime.
I/sysproc ( 1026): System server: starting Android services.
I/sysproc ( 1026): System server: entering thread pool.
I/SystemServer( 1026): Entered the Android system server!
I/SystemServer( 1026): Entropy Service
I/SystemServer( 1026): Power Manager
I/SystemServer( 1026): Activity Manager
D/libEGL  ( 1041): loaded /system/lib/egl/libGLES_android.so
D/libEGL  ( 1041): loaded /system/lib/egl/libEGL_tegra.so
D/libEGL  ( 1041): loaded /system/lib/egl/libGLESv1_CM_tegra.so
D/libEGL  ( 1041): loaded /system/lib/egl/libGLESv2_tegra.so
W/zipro   ( 1041): Unable to open zip '/data/local/bootanimation.zip': No such file or directory
W/zipro   ( 1041): Unable to open zip '/system/media/bootanimation.zip': No such file or directory
I/ActivityManager( 1026): Memory class: 48
E/SurfaceFlinger( 1026): eglSwapBuffers: EGL error 0x3008 (EGL_BAD_DISPLAY)
I/SystemServer( 1026): Telephony Registry
I/SystemServer( 1026): Package Manager
I/installd(  950): new connection
I/Installer( 1026): connecting...
I/PackageManager( 1026): Libs: android.test.runner:/system/framework/android.test.runner.jar com.nvidia.display:/system/framework/com.nvidia.display.jar javax.obex:/system/framework/javax.obex.jar com.nvidia.graphics:/system/framework/com.nvidia.graphics.jar
I/PackageManager( 1026): Features: android.hardware.wifi android.hardware.location.network android.hardware.telephony android.hardware.location android.hardware.touchscreen.multitouch android.hardware.camera android.hardware.bluetooth android.hardware.microphone android.hardware.telephony.gsm android.hardware.camera.autofocus android.software.live_wallpaper android.hardware.sensor.accelerometer android.hardware.touchscreen android.hardware.camera.flash
W/PackageManager( 1026): Running ENG build: no pre-dexopt!
D/PackageManager( 1026): Scanning app dir /system/framework
D/PackageManager( 1026): Scanning app dir /system/app
D/dhcpcd  (  954): sending DHCP_DISCOVER with xid 0xf200d944, next in 7.09 seconds
D/dhcpcd  (  954): offered 10.250.51.157 from 10.250.0.22
D/dhcpcd  (  954): sending DHCP_REQUEST with xid 0xf200d944, next in 3.89 seconds
D/dhcpcd  (  954): ignoring offer of 10.250.51.157 from 10.250.0.21
D/dhcpcd  (  954): acknowledged 10.250.51.157 from 10.250.0.22
W/PackageParser( 1026): No actions in intent filter at /system/app/Bluetooth.apk Binary XML file line #124
D/dhcpcd  (  954): checking 10.250.51.157 is available on attached networks
D/dhcpcd  (  954): sending ARP probe (1 of 3), next in 1.20 seconds
D/PackageManager( 1026): Scanning app dir /data/app
W/PackageParser( 1026): Unknown element under <manifest>: compatible-screens at /data/app/org.mozilla.fennec-1.apk Binary XML file line #13
D/PackageManager( 1026): Scanning app dir /data/app-private
I/PackageManager( 1026): Time to scan packages: 2.19 seconds
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH in package com.android.providers.contacts
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH.cp in package com.android.providers.contacts
W/PackageManager( 1026): Unknown permission com.google.android.gm.permission.WRITE_GMAIL in package com.android.settings
W/PackageManager( 1026): Unknown permission com.google.android.gm.permission.READ_GMAIL in package com.android.settings
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH in package com.android.settings
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH.mail in package com.android.contacts
W/PackageManager( 1026): Unknown permission android.permission.ADD_SYSTEM_SERVICE in package com.android.phone
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH in package com.android.providers.calendar
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH.cl in package com.android.providers.calendar
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.ACCESS_GOOGLE_PASSWORD in package com.android.development
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH in package com.android.development
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH.ALL_SERVICES in package com.android.development
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH.YouTubeUser in package com.android.development
W/PackageManager( 1026): Not granting permission android.permission.SEND_DOWNLOAD_COMPLETED_INTENTS to package com.android.browser (protectionLevel=2 flags=0x1be45)
W/PackageManager( 1026): Not granting permission android.permission.REBOOT to package com.mozilla.SUTAgentAndroid (protectionLevel=3 flags=0xbe46)
W/PackageManager( 1026): Not granting permission android.permission.DEVICE_POWER to package com.mozilla.SUTAgentAndroid (protectionLevel=2 flags=0xbe46)
W/PackageManager( 1026): Not granting permission android.permission.INSTALL_PACKAGES to package com.mozilla.SUTAgentAndroid (protectionLevel=3 flags=0xbe46)
W/PackageManager( 1026): Not granting permission android.permission.STATUS_BAR to package com.mozilla.SUTAgentAndroid (protectionLevel=3 flags=0xbe46)
W/PackageManager( 1026): Not granting permission android.permission.SET_TIME to package com.mozilla.SUTAgentAndroid (protectionLevel=3 flags=0xbe46)
W/PackageManager( 1026): Not granting permission android.permission.WRITE_SECURE_SETTINGS to package com.mozilla.SUTAgentAndroid (protectionLevel=3 flags=0xbe46)
W/PackageManager( 1026): Not granting permission android.permission.DEVICE_POWER to package com.android.deskclock (protectionLevel=2 flags=0xbe45)
D/dhcpcd  (  954): sending ARP probe (2 of 3), next in 1.11 seconds
I/SystemServer( 1026): Account Manager
I/SystemServer( 1026): Content Manager
I/ActivityThread( 1026): Publishing provider settings: com.android.providers.settings.SettingsProvider
I/SystemServer( 1026): System Content Providers
I/SystemServer( 1026): Battery Service
D/        (  953): NVRM_DAEMON(808): rt_exist=2, add client ref
I/SystemServer( 1026): Lights Service
I/SystemServer( 1026): Vibrator Service
I/SystemServer( 1026): Alarm Manager
I/SystemServer( 1026): Init Watchdog
I/SystemServer( 1026): Sensor Service
I/SystemServer( 1026): Window Manager
D/        (  953): NVRM_DAEMON(808): rt_exist=2, add client ref
I/SystemServer( 1026): Bluetooth Service
I/EventHub( 1026): New device: path=/dev/input/event3 name=accelerometer_tegra id=0x10000 (of 0x1) index=1 fd=63 classes=0x0
I/SystemServer( 1026): Device Policy
I/SystemServer( 1026): Status Bar
I/EventHub( 1026): New keyboard: device->id=0x10001 devname='nvodm_touch' propName='hw.keyboards.65537.devname' keylayout='/system/usr/keylayout/qwerty.kl'
I/EventHub( 1026): New device: path=/dev/input/event2 name=nvodm_touch id=0x10001 (of 0x2) index=2 fd=66 classes=0x15
I/SystemServer( 1026): Clipboard Service
I/SystemServer( 1026): Input Method Service
I/InputManagerService( 1026): Enabled input methods: com.android.inputmethod.latin/.LatinIME
I/SystemServer( 1026): NetStat Service
I/SystemServer( 1026): NetworkManagement Service
I/SystemServer( 1026): Connectivity Service
D/Tethering( 1026): Tethering starting
E/EventHub( 1026): could not get driver version for /dev/input/mouse0, Not a typewriter
I/WifiService( 1026): WifiService starting up with Wi-Fi enabled
D/NetworkManagmentService( 1026): Registering observer
I/SystemServer( 1026): Throttle Service
I/SystemServer( 1026): Accessibility Manager
I/SystemServer( 1026): Mount Service
I/PackageManager( 1026): Updating external media status from unmounted to mounted
I/SystemServer( 1026): Notification Manager
D/VoldCmdListener(  941): volume list
I/MountService( 1026): Media already mounted on daemon connection
W/MountService( 1026): Skipping unknown volume '/mnt/usbdisk'
D/VoldCmdListener(  941): share status ums
I/SystemServer( 1026): Device Storage Monitor
I/SystemServer( 1026): Location Manager
I/SystemServer( 1026): Search Service
I/SystemServer( 1026): DropBox Service
I/SystemServer( 1026): Wallpaper Service
I/SystemServer( 1026): Audio Service
I/EventHub( 1026): New keyboard: device->id=0x10002 devname='nvec keyboard' propName='hw.keyboards.65538.devname' keylayout='/system/usr/keylayout/nvec_keyboard.kl'
I/EventHub( 1026): New device: path=/dev/input/event1 name=nvec keyboard id=0x10002 (of 0x3) index=3 fd=71 classes=0x3
E/EventHub( 1026): could not get driver version for /dev/input/mice, Not a typewriter
D/        (  953): NVRM_DAEMON(808): rt_exist=1, add client ref
D/AudioHardwareInterface(  946): setMode(NORMAL)
W/AudioPolicyManager(  946): setPhoneState() setting same state 0
I/EventHub( 1026): New keyboard: device->id=0x10003 devname='gpio-keys' propName='hw.keyboards.65539.devname' keylayout='/system/usr/keylayout/gpio-keys.kl'
I/EventHub( 1026): New device: path=/dev/input/event0 name=gpio-keys id=0x10003 (of 0x4) index=4 fd=74 classes=0x1
I/KeyInputQueue( 1026): Device added: id=0x10003, name=gpio-keys, classes=1
I/KeyInputQueue( 1026): Device added: id=0x10002, name=nvec keyboard, classes=3
I/KeyInputQueue( 1026): Device added: id=0x0, name=nvodm_touch, classes=15
I/KeyInputQueue( 1026):   X: min=0 max=4095 flat=0 fuzz=0
I/KeyInputQueue( 1026):   Y: min=0 max=4095 flat=0 fuzz=0
I/KeyInputQueue( 1026):   Pressure: min=0 max=100 flat=0 fuzz=0
I/KeyInputQueue( 1026):   Size: min=0 max=8 flat=0 fuzz=0
I/KeyInputQueue( 1026): No virtual keys found
I/KeyInputQueue( 1026): Ignoring non-input device: id=0x10000, name=accelerometer_tegra
I/SystemServer( 1026): Headset Observer
W/HeadsetObserver( 1026): This kernel does not have wired headset support
I/SystemServer( 1026): Dock Observer
W/DockObserver( 1026): This kernel does not have dock station support
I/SystemServer( 1026): UI Mode Manager Service
I/SystemServer( 1026): Backup Service
V/BackupManagerService( 1026): No ancestral data
I/BackupManagerService( 1026): Found stale backup journal, scheduling:
I/BackupManagerService( 1026):     + android
I/BackupManagerService( 1026):     + com.android.inputmethod.latin
I/BackupManagerService( 1026):     + com.android.browser
I/BackupManagerService( 1026):     + com.android.providers.userdictionary
I/BackupManagerService( 1026):     + com.android.providers.settings
I/BackupManagerService( 1026): Backup enabled => false
I/SystemServer( 1026): AppWidget Service
I/SystemServer( 1026): Recognition Service
I/WindowManager( 1026): SAFE MODE not enabled
D/VoldCmdListener(  941): share status ums
D/StorageNotification( 1026): Startup with UMS connection false (media state mounted)
I/SystemServer( 1026): DiskStats Service
W/DevicePolicyManagerService( 1026): failed parsing /data/system/device_policies.xml java.io.FileNotFoundException: /data/system/device_policies.xml (No such file or directory)
I/ActivityManager( 1026): Config changed: { scale=1.0 imsi=0/0 loc=en_US touch=3 keys=2/1/2 nav=1/1 orien=2 layout=19 uiMode=0 seq=1}
I/power   ( 1026): *** set_screen_state 1
D/        (  953): NVRM_DAEMON(808): rt_exist=2, add client ref
I/Zygote  ( 1026): Process: zygote socket opened
D/PowerManagerService( 1026): system ready!
I/ActivityManager( 1026): Sending system update to: ComponentInfo{com.android.providers.contacts/com.android.providers.contacts.ContactsUpgradeReceiver}
I/ActivityManager( 1026): Sending system update to: ComponentInfo{com.android.providers.calendar/com.android.providers.calendar.CalendarUpgradeReceiver}
I/ActivityManager( 1026): Start proc android.process.acore for broadcast com.android.providers.contacts/.ContactsUpgradeReceiver: pid=1200 uid=10015 gids={3003, 1015}
I/ActivityManager( 1026): Launching preboot mode app: ProcessRecord{484a79d0 1200:android.process.acore/10015}
W/StatusBar( 1026): No icon ID for slot ime
I/ActivityManager( 1026): Start proc com.android.providers.calendar for broadcast com.android.providers.calendar/.CalendarUpgradeReceiver: pid=1211 uid=10010 gids={3003}
I/ActivityManager( 1026): Launching preboot mode app: ProcessRecord{48502520 1211:com.android.providers.calendar/10010}
D/StatusBar( 1026): DISABLE_EXPAND: yes
I/ActivityManager( 1026): Starting activity: Intent { act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10000000 cmp=com.android.launcher/com.android.launcher2.Launcher }
I/Process ( 1026): Sending signal. PID: 1200 SIG: 9
I/Process ( 1026): Sending signal. PID: 1211 SIG: 9
I/ActivityManager( 1026): Removing system update proc: ProcessRecord{484a79d0 1200:android.process.acore/10015}
I/ActivityManager( 1026): Removing system update proc: ProcessRecord{48502520 1211:com.android.providers.calendar/10010}
I/ActivityManager( 1026): System now ready
I/SystemServer( 1026): Making services ready
I/ActivityManager( 1026): Config changed: { scale=1.0 imsi=0/0 loc=en_US touch=3 keys=2/1/2 nav=1/1 orien=2 layout=19 uiMode=17 seq=2}
W/RecognitionManagerService( 1026): no available voice recognition services found
D/libhardware_legacy( 1026): no GPS hardware on this device
I/ActivityManager( 1026): Start proc com.android.inputmethod.latin for service com.android.inputmethod.latin/.LatinIME: pid=1232 uid=10007 gids={}
D/NetworkManagmentService( 1026): Registering observer
E/ThrottleService( 1026): Could not open GPS configuration file /etc/gps.conf
I/ActivityManager( 1026): Start proc com.android.phone for added application com.android.phone: pid=1240 uid=1001 gids={3002, 3001, 3003, 1015}
I/ActivityManager( 1026): Start proc com.android.launcher for activity com.android.launcher/com.android.launcher2.Launcher: pid=1245 uid=10018 gids={}
I/ActivityManager( 1026): Start proc com.android.settings for broadcast com.android.settings/.widget.SettingsAppWidgetProvider: pid=1254 uid=1000 gids={3002, 3001, 3003}
W/ActivityManager( 1026): Unable to start service Intent { act=@0 }: not found
D/dhcpcd  (  954): sending ARP probe (3 of 3), next in 2.00 seconds
W/ActivityManager( 1026): Unable to start service Intent { act=@0 }: not found
I/ActivityManager( 1026): Start proc android.process.acore for content provider com.android.providers.userdictionary/.UserDictionaryProvider: pid=1272 uid=10015 gids={3003, 1015}
D/Tethering( 1026): wlan0 is not a tetherable iface, ignoring
I//system/bin/tc(  942): Cannot find device "rmnet0"
I/logwrapper(  942): /system/bin/tc terminated by exit(1)
I//system/bin/tc(  942): Cannot find device "rmnet0"
I/logwrapper(  942): /system/bin/tc terminated by exit(1)
I//system/bin/tc(  942): Cannot find device "ifb0"
I/logwrapper(  942): /system/bin/tc terminated by exit(1)
I/ActivityThread( 1245): Publishing provider com.android.launcher2.settings: com.android.launcher2.LauncherProvider
I/ActivityThread( 1272): Publishing provider com.android.social: com.android.providers.contacts.SocialProvider
I/ActivityThread( 1240): Publishing provider mms: com.android.providers.telephony.MmsProvider
D/VoldCmdListener(  941): asec list
I/ActivityThread( 1272): Publishing provider applications: com.android.providers.applications.ApplicationsProvider
I/PackageManager( 1026): No secure containers on sdcard
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH in package com.android.providers.contacts
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH.cp in package com.android.providers.contacts
W/PackageManager( 1026): Unknown permission com.google.android.gm.permission.WRITE_GMAIL in package com.android.settings
W/PackageManager( 1026): Unknown permission com.google.android.gm.permission.READ_GMAIL in package com.android.settings
I/ActivityThread( 1240): Publishing provider sms: com.android.providers.telephony.SmsProvider
I/ActivityThread( 1240): Publishing provider telephony: com.android.providers.telephony.TelephonyProvider
I/ActivityThread( 1240): Publishing provider icc: com.android.phone.IccProvider
I/ActivityThread( 1240): Publishing provider mms-sms: com.android.providers.telephony.MmsSmsProvider
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH in package com.android.settings
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH.mail in package com.android.contacts
W/PackageManager( 1026): Unknown permission android.permission.ADD_SYSTEM_SERVICE in package com.android.phone
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH in package com.android.providers.calendar
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH.cl in package com.android.providers.calendar
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.ACCESS_GOOGLE_PASSWORD in package com.android.development
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH in package com.android.development
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH.ALL_SERVICES in package com.android.development
W/PackageManager( 1026): Unknown permission com.google.android.googleapps.permission.GOOGLE_AUTH.YouTubeUser in package com.android.development
W/PackageManager( 1026): Not granting permission android.permission.SEND_DOWNLOAD_COMPLETED_INTENTS to package com.android.browser (protectionLevel=2 flags=0x1be45)
W/PackageManager( 1026): Not granting permission android.permission.REBOOT to package com.mozilla.SUTAgentAndroid (protectionLevel=3 flags=0xbe46)
W/PackageManager( 1026): Not granting permission android.permission.DEVICE_POWER to package com.mozilla.SUTAgentAndroid (protectionLevel=2 flags=0xbe46)
W/PackageManager( 1026): Not granting permission android.permission.INSTALL_PACKAGES to package com.mozilla.SUTAgentAndroid (protectionLevel=3 flags=0xbe46)
W/PackageManager( 1026): Not granting permission android.permission.STATUS_BAR to package com.mozilla.SUTAgentAndroid (protectionLevel=3 flags=0xbe46)
W/PackageManager( 1026): Not granting permission android.permission.SET_TIME to package com.mozilla.SUTAgentAndroid (protectionLevel=3 flags=0xbe46)
W/PackageManager( 1026): Not granting permission android.permission.WRITE_SECURE_SETTINGS to package com.mozilla.SUTAgentAndroid (protectionLevel=3 flags=0xbe46)
W/PackageManager( 1026): Not granting permission android.permission.DEVICE_POWER to package com.android.deskclock (protectionLevel=2 flags=0xbe45)
I/ActivityThread( 1272): Publishing provider contacts;com.android.contacts: com.android.providers.contacts.ContactsProvider2
D/WifiService( 1026): ACTION_BATTERY_CHANGED pluggedType: 1
D/PhoneApp( 1240): onCreate: mProximityWakeLock: null
D/PhoneApp( 1240): Resetting audio state/mode: IDLE
W/ActivityManager( 1026): Unable to start service Intent { act=com.android.ussd.IExtendedNetworkService }: not found
I/ActivityThread( 1272): Publishing provider call_log: com.android.providers.contacts.CallLogProvider
I/ActivityThread( 1272): Publishing provider user_dictionary: com.android.providers.userdictionary.UserDictionaryProvider
D/MobileDataStateTracker( 1026): default Received state= DISCONNECTED, old= DISCONNECTED, reason= radioTurnedOff, apnTypeList= default
D/BT HSHFP( 1240): Starting BluetoothHeadsetService
D/MobileDataStateTracker( 1026): default Received state= DISCONNECTED, old= DISCONNECTED, reason= gprsDetached, apnTypeList= default
D/DataConnectionTracker( 1240): enableApnType(default), isApnTypeActive = false and state = IDLE
D/DataConnectionTracker( 1240): type not available
I/ActivityManager( 1026): Start proc android.process.media for broadcast com.android.providers.downloads/.DownloadReceiver: pid=1381 uid=10004 gids={1015, 2001, 3003}
D/Tethering( 1026): Tethering got CONNECTIVITY_ACTION
D/Tethering( 1026): MasterInitialState.processMessage what=3
E/HierarchicalStateMachine( 1026): TetherMaster - unhandledMessage: msg.what=3
I/ActivityThread( 1381): Publishing provider media: com.android.providers.media.MediaProvider
V/MediaProvider( 1381): Attached volume: internal
V/MediaProvider( 1381): /mnt/sdcard volume ID: 892743735
V/MediaProvider( 1381): Attached volume: external
I/ActivityThread( 1381): Publishing provider downloads: com.android.providers.downloads.DownloadProvider
I/ActivityThread( 1381): Publishing provider drm: com.android.providers.drm.DrmProvider
D/PowerManagerService( 1026): bootCompleted
I/SurfaceFlinger( 1026): Boot is finished (6055 ms)
D/OtaStartupReceiver( 1240): Not a CDMA phone, no need to process OTA
I/SearchManagerService( 1026): Building list of searchable activities
I/ActivityManager( 1026): Start proc com.android.deskclock for broadcast com.android.deskclock/.AlarmInitReceiver: pid=1400 uid=10029 gids={}
I/RecoverySystem( 1026): No recovery log file
D/dhcpcd  (  954): leased 10.250.51.157 for 10800 seconds
D/dhcpcd  (  954): adding IP address 10.250.51.157/22
D/dhcpcd  (  954): adding route to 0.0.0.0/0 via 10.250.48.1
D/dhcpcd  (  954): executing `/system/etc/dhcpcd/dhcpcd-run-hooks', reason BOUND
I/ActivityThread( 1400): Publishing provider com.android.deskclock: com.android.deskclock.AlarmProvider
D/dhcpcd  (  954): forking to background
I/ActivityManager( 1026): Start proc com.android.bluetooth for broadcast com.android.bluetooth/.opp.BluetoothOppReceiver: pid=1433 uid=10017 gids={3003, 3002, 3001, 1015}
I/ActivityThread( 1433): Publishing provider com.android.bluetooth.opp: com.android.bluetooth.opp.BluetoothOppProvider
I/ActivityManager( 1026): Start proc com.android.email for broadcast com.android.email/com.android.exchange.BootReceiver: pid=1441 uid=10014 gids={3003, 1015}
I/ActivityThread( 1441): Publishing provider com.android.email.provider: com.android.email.provider.EmailProvider
I/ActivityThread( 1441): Publishing provider com.android.email.attachmentprovider: com.android.email.provider.AttachmentProvider
I/ActivityThread( 1441): Publishing provider com.android.exchange.provider: com.android.exchange.provider.ExchangeProvider
D/Exchange( 1441): BootReceiver onReceive
D/EAS SyncManager( 1441): !!! EAS SyncManager, onCreate
I/ActivityManager( 1026): Start proc com.android.providers.calendar for broadcast com.android.providers.calendar/.CalendarReceiver: pid=1455 uid=10010 gids={3003}
I/ActivityThread( 1455): Publishing provider com.android.calendar: com.android.providers.calendar.CalendarProvider2
D/EAS SyncManager( 1441): !!! EAS SyncManager, onStartCommand
D/EAS SyncManager( 1441): !!! EAS SyncManager, stopping self
D/Eas Debug( 1441): Logging: 
D/EAS SyncManager( 1441): !!! EAS SyncManager, onDestroy
I/ActivityManager( 1026): Start proc com.android.mms for broadcast com.android.mms/.transaction.MmsSystemEventReceiver: pid=1470 uid=10006 gids={3003, 1015}
D/Calendar( 1455): missed alarms found: 0
I/ActivityThread( 1470): Publishing provider com.android.mms.SuggestionsProvider: com.android.mms.SuggestionsProvider
D/MediaScannerService( 1381): start scanning volume internal
E/MediaScanner( 1381): new omx scanner
I/NvxDrmPlay( 1381): NvxCommonDrmPlayInit
I/NvxDrmPlay( 1381): NvxDrmPlayDeInit
I/ActivityManager( 1026): Start proc com.mozilla.SUTAgentAndroid for broadcast com.mozilla.SUTAgentAndroid/.SUTStartupIntentReceiver: pid=1489 uid=10031 gids={3003, 1015, 3002, 3001}
I/ActivityManager( 1026): Starting activity: Intent { flg=0x10000000 cmp=com.mozilla.SUTAgentAndroid/.SUTAgentAndroid }
I/ActivityManager( 1026): Start proc com.mozilla.watcher for broadcast com.mozilla.watcher/.WatcherReceiver: pid=1500 uid=10032 gids={}
I/ActivityManager( 1026): Start proc com.android.quicksearchbox for broadcast com.android.quicksearchbox/.SearchWidgetProvider: pid=1509 uid=10009 gids={3003}
I/global  ( 1500): Default buffer size used in BufferedReader constructor. It would be better to be explicit if an 8k-char buffer is required.
I/global  ( 1500): Default buffer size used in BufferedReader constructor. It would be better to be explicit if an 8k-char buffer is required.
I/global  ( 1500): Default buffer size used in BufferedReader constructor. It would be better to be explicit if an 8k-char buffer is required.
I/global  ( 1500): Default buffer size used in BufferedReader constructor. It would be better to be explicit if an 8k-char buffer is required.
W/Service ( 1500): setForeground: ignoring old API call on com.mozilla.watcher.WatcherService
I/SUTAgentAndroid( 1489): Deleted old command logfile: /mnt/sdcard/1970-01-02-sutcommands.txt
D/MediaScanner( 1381):  prescan time: 109ms
D/MediaScanner( 1381):     scan time: 247ms
D/MediaScanner( 1381): postscan time: 1ms
D/MediaScanner( 1381):    total time: 357ms
D/MediaScannerService( 1381): done scanning volume internal
I/ActivityThread( 1509): Publishing provider com.android.quicksearchbox.google: com.android.quicksearchbox.google.GoogleSuggestionProvider
I/ActivityManager( 1026): Start proc com.android.music for broadcast com.android.music/.MediaAppWidgetProvider: pid=1524 uid=10002 gids={3003, 1015}
I/ActivityManager( 1026): Start proc com.cooliris.media for broadcast com.cooliris.media/com.cooliris.cache.BootReceiver: pid=1532 uid=10013 gids={1015, 3003}
I/ActivityThread( 1532): Publishing provider com.cooliris.picasa.contentprovider: com.cooliris.picasa.PicasaContentProvider
I/BootReceiver( 1532): Got intent with action android.intent.action.MEDIA_SCANNER_FINISHED
D/dhcpcd  ( 1432): sending ARP announce (1 of 2), next in 2.00 seconds
D/dhcpcd  ( 1432): sending ARP announce (2 of 2)
D/dhcpcd  ( 1432): renew in 5396 seconds
D/WifiService( 1026): ACTION_BATTERY_CHANGED pluggedType: 1
I/global  ( 1489): Default buffer size used in BufferedInputStream constructor. It would be better to be explicit if an 8k buffer is required.
I/SUTAgentAndroid( 1489): 2012/07/28 05:32:50:055 : 10.250.48.200 : ps
I/SUTAgentAndroid( 1489): 2012/07/28 05:32:50:143 : 10.250.48.200 : pull /mnt/sdcard/tests/reftest/reftest.log
I/SUTAgentAndroid( 1489): 2012/07/28 05:32:50:219 : 10.250.48.200 : hash /mnt/sdcard/tests/reftest/reftest.log
I/SUTAgentAndroid( 1489): 2012/07/28 05:32:50:265 : 10.250.48.200 : isdir /mnt/sdcard/tests/reftest/profile/minidumps/
I/SUTAgentAndroid( 1489): 2012/07/28 05:32:50:301 : 10.250.48.200 : cd /mnt/sdcard/tests/reftest/profile/minidumps
I/SUTAgentAndroid( 1489): 2012/07/28 05:32:50:332 : 10.250.48.200 : cwd
I/SUTAgentAndroid( 1489): 2012/07/28 05:32:50:364 : 10.250.48.200 : cd /mnt/sdcard/tests/reftest/profile/minidumps
I/SUTAgentAndroid( 1489): 2012/07/28 05:32:50:396 : 10.250.48.200 : ls
I/SUTAgentAndroid( 1489): 2012/07/28 05:32:50:427 : 10.250.48.200 : pull /mnt/sdcard/tests/reftest/reftest.log
I/SUTAgentAndroid( 1489): 2012/07/28 05:32:50:477 : 10.250.48.200 : hash /mnt/sdcard/tests/reftest/reftest.log
I/SUTAgentAndroid( 1489): 2012/07/28 05:32:50:513 : 10.250.48.200 : rmdr /mnt/sdcard/tests/reftest/profile
I/SUTAgentAndroid( 1489): 2012/07/28 05:32:50:998 : 10.250.48.200 : rmdr /mnt/sdcard/tests/reftest

Comment 13

[Joel Maher ( :jmaher ) (UTC -8)]

This has a 57 second delay where we normally wait 5 seconds between these commands:
2012/07/28 05:31:53:960 : 10.250.48.200 : hash /mnt/sdcard/tests/reftest/reftest.log
2012/07/28 05:32:50:055 : 10.250.48.200 : ps


This would indicate that we don't have a second foopy sending commands.  I don't see a lot of reboot commands, the 1 and only 1 in 40 minutes I see is:
2012/07/28 05:33:31:431 : 10.250.48.200 : rebt 10.250.48.200 50317


Is this expected?

Comment 15

[Justin Wood (:Callek)]

Fixed by ATeam find of watcher being the cause of the reboot's during tests