/usr/bin/PmBtStack -C /dev/btuart -B 115200 00:1D:FE:XX:XX:XX 1 0x3afc 16888 1 # BluetoothMonitor Setting debug level to 0x2 [BTMtr]: Starting BluetoothMonitor... [BTMtr]: Running PmBtStack [BTMtr]: Forked PmBtStack child process with id of 2840 {BTMtr]: Waiting for bsl0 to come up... [BTMtr]: Checking if stack is up completely ls: /dev/bt_uart: No such file or directory 371: 1122 TWL4030 twl4030-madc 373: 190 TWL4030 twl4030_usb, rtc0 bsl0 Link encap:Ethernet HWaddr 00:1D:FE:34:42:BB inet addr:10.1.1.10 Bcast:10.1.1.255 Mask:255.255.255.0 UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:0 errors:0 dropped:0 overruns:0 frame:0 TX packets:0 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:500 RX bytes:0 (0.0 B) TX bytes:0 (0.0 B) [BTMtr]: Running PmBtEngine [BTMtr]: Forked PmBtEngine child process with id of 2851 [BTMtr]: AllExists: Entered [BTMtr]: IsExists: pid=2851 [BTMtr]: IsExists: pid=2840 [BTMtr]: Waiting till any process quits... Setting debug level to 0x2 Starting PmBtEngine daemon... Initializing BtEngine components [ MEM ] Initializing [ MEM ] Initializing - list 0x400992c0 [ MEM ] Starting [CFG]: BtConfigInit: Initializing BT configuration module [Core]: In PmBtEngineEventHandlerInitialize [Core]: BtEngineEventHandler created successfully [BSF]: calling init_pmalloc [BSF]: calling init_sched [BSF]: calling init_bchs_msg_converter [BSF]: calling SPP_init_converter [BSF]: calling HFG_init_converter [BSF]: calling BSL_init_converter [BSF]: calling SC_init_converter [BSF]: calling CM_init_converter [BSF]: calling SD_init_converter [BSF]: calling AV_init_converter [BSF]: calling AVRCP_init_converter [BSF]: calling PAS_init_converter [BSF]: calling peer_register_converter [BSF]: calling peer_com_init sched: external send registered peer_com: connection to server established... peer_com: performing peer_com version 2 handshake... peer_com: server has replied to handshake, code 0x0001... [BSF]: SchedulerThreadFn: Sched started [BSF]: Bluetooth--> init_test [SIG]: Received SIGTERM, Stopping BT Engine [SIG]: Received Signal to stop, Stopping BT Engine *****ERROR:[BSF]: WriteSettingsByRadioVersion: Error waiting for getting local version (process:2851): Powerd-DEBUG: IdlerShm already exists... reusing ** (process:2851): DEBUG: _powerd_server_up connected was true (powerd is already running) [PWR]: Initializing Power [Core]: Successfully registered profile -- pan [Core]: Successfully registered profile -- a2dp [A2DP]: BtA2dpProfMgrRegisterInit:A2DP Profile Set IPC Registration func, err= 0x0 [Core]: Successfully registered profile -- hfp/hsp [HFG]: BtHfgProfMgrRegisterInit:HFG Profile registration status 0x0 [HFG]: BtHfgProfMgrRegisterInit:HFG Profile Set IPC Registration func, err= 0x0 [Core]: Successfully registered profile -- pbap [Core]: Successfully registered profile -- avrcp [AVRCP]: BtAvrcpProfMgrRegisterInit:AVRCP Profile Set IPC Registration func, err= 0x0 [Core]: Successfully registered profile -- BT Co-Existance Profile [COEX]: CoExProfMgrRegisterInit:CoEx Profile registration status 0x0 [COEX]: CoExProfMgrRegisterInit:CoEx Profile Set IPC Registration func, err= 0x0 [Core]: Successfully registered profile -- BT Test Mode [TM]: TmProfMgrRegisterInit:Tm Profile registration status 0x0 [TM]: TmProfMgrRegisterInit:Tm Profile Set IPC Registration func, err= 0x0 [Core]: BtProfMgrStartupProfiles: Entered [Core]: Initializing profile pan [Core]: Initializing profile a2dp [Core]: Initializing profile hfp/hsp [Core]: Initializing profile pbap [Core]: Initializing profile avrcp [Core]: Initializing profile BT Co-Existance Profile [Core]: Initializing profile BT Test Mode (process:2851): LunaService-CRITICAL **: Error in base.c:566 (process:2851): LunaService-CRITICAL **: Can't request name com.palm.bluetooth with bus *****ERROR:[IPC]: PmBtMsgInit: Error intializing Luna service *****ERROR:[INIT]: InitializeComponents: Messaging Init failed 0x8100300 [Core]: Shutting down profile pan *****ERROR:[Core]: Profile pan failed to BtProfShutdown [Core]: Shutting down profile a2dp [Core]: Shutting down profile hfp/hsp [HFG]: Waiting for deactivation [HFG]: Deactivated [Core]: Shutting down profile pbap *****ERROR:[PBAP]: PbapWaitForDeactivate: Error in waiting to deactivate PBAP [Core]: Shutting down profile avrcp [Core]: Shutting down profile BT Co-Existance Profile [Core]: Shutting down profile BT Test Mode [BSF]:sched_task_deinit [BSF]: SchedulerThreadFn: Sched is closed [BSF]:peer_com_deinit [BSF]:deinit_sched [BSF]:deinit_pmalloc [CFG]: BtConfigDeinit: Bt Config mgr shutting down [ MEM ] Stopping [ MEM ] Shutting down *****ERROR:Failed to initialize engine components errno=0x8100300 Tearing down components *** glibc detected *** /usr/bin/PmBtEngine: double free or corruption (!prev): 0x000c5620 *** *****ERROR:[SIG]: Received SIGABRT, Stopping BT Engine *****ERROR:[SIG]: Received Signal to stop, Forcing BT Engine to stop *****ERROR:[BTMtr]: Abnormal teardown of BT Component, count=1 [BTMtr]: Engine process exited Abnormally. Process has died 1 times. [BTMtr]: **********************************Killing pid = 2840, component = PmBtStack [BTMtr]: Kill signal sent... [BTMtr]: Signal successful Waiting for PmBtStack to exit... PmBtContacts: no process killed sched: external send registered peer_com: waiting for connection... sched: external send registered peer_com: waiting for connection... Crystal frequency: 26.0MHz BT address token: '00:1D:FE:34:42:BB' BT_ADDR: 00:1d:fe:34:42:bb (3442bb-fe-001d) sched: external send registered peer_com: waiting for connection... Crystal frequency: 26.0MHz BT address token: '00:1D:FE:34:42:BB' BT_ADDR: 00:1d:fe:34:42:bb (3442bb-fe-001d) [BTMtr]: Clean: Entered, sig=0x2 [BTMtr]: Stopping Bluetooth engine and stack... [BTMtr]: **********************************Killing pid = 2851, component = PmBtEngine [BTMtr]: Kill signal sent... *****ERROR:[BTMtr]: Signal failed, Err = 0xffffffff [BTMtr]: **********************************Killing pid = 2840, component = PmBtStack [BTMtr]: Kill signal sent... [BTMtr]: Signal successful Waiting for PmBtStack to exit... PmBtStack has exited [BTMtr]: Exiting BluetoothMonitor! root@castle:/dev# tail -n 100 /var/log/messages 2009-06-14T01:06:30.577239Z [58424] castle user.warning audiod: _pulseStatus: sink 2 (stream 7) opened 2009-06-14T01:06:30.596405Z [58424] castle user.info powerd: BATTERY: (1181.800049mAh, 99%, 100%_ui, 29C, -475mA, 4099mV, authentic) 2009-06-14T01:06:30.955200Z [58424] castle user.warning audiod: _pulseStatus: pulse reports sink 2 (stream 7) closed 2009-06-14T01:06:31.157958Z [58424] castle user.warning audiod: closeSink: sink 2 processed closed after a delay 2009-06-14T01:06:31.270935Z [58424] castle user.info powerd: POWERD-TIMEOUT: _timeout_fire (com.palm.power,misc_timer-1114 => luna://com.palm.power/time/internalAlarmFired) 2009-06-14T01:06:31.271179Z [58424] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStart: (com.palm.power.timeout_fired) for 5000ms => true 2009-06-14T01:06:31.294128Z [58424] castle user.info powerd: POWERD-ALARM: Alarm ((null) (null) misc_timer) fired at Sun Jun 14 01:06:31 2009 2009-06-14T01:06:31.911895Z [58425] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStart: (com.palm.display-lock.timer) for 3000ms => true 2009-06-14T01:06:32.410888Z [58425] castle user.warning powerd: POWERD-SUSPEND: IdleCheck can't sleep because because an activity is active: 2009-06-14T01:06:32.411071Z [58425] castle user.info powerd: POWERD-SUSPEND: Activities since wake: 2009-06-14T01:06:32.411193Z [58425] castle user.info powerd: POWERD-ACTIVITY: (com.palm.power.timeout_fired) for 5000 ms, expiry in 3857 ms 2009-06-14T01:06:33.154449Z [58426] castle local2.info chat[3386]: ATDT#777^M^M 2009-06-14T01:06:33.154663Z [58426] castle local2.info chat[3386]: CONNECT 2009-06-14T01:06:33.154815Z [58426] castle local2.info chat[3386]: -- got it 2009-06-14T01:06:33.154937Z [58426] castle local2.info chat[3386]: send (^M) 2009-06-14T01:06:33.161773Z [58426] castle daemon.info pppd[3383]: Serial connection established. 2009-06-14T01:06:33.161987Z [58426] castle daemon.debug pppd[3383]: using channel 2 2009-06-14T01:06:33.166259Z [58426] castle daemon.info pppd[3383]: Using interface ppp0 2009-06-14T01:06:33.166442Z [58426] castle daemon.notice pppd[3383]: Connect: ppp0 <--> /dev/tts/modem0 2009-06-14T01:06:33.178009Z [58426] castle daemon.debug pppd[3383]: sent [LCP ConfReq id=0x1 ] 2009-06-14T01:06:33.183624Z [58426] castle daemon.debug pppd[3383]: rcvd [LCP ConfReq id=0x2 ] 2009-06-14T01:06:33.183837Z [58426] castle daemon.debug pppd[3383]: sent [LCP ConfAck id=0x2 ] 2009-06-14T01:06:33.183959Z [58426] castle daemon.debug pppd[3383]: rcvd [LCP ConfAck id=0x1 ] 2009-06-14T01:06:33.219482Z [58426] castle daemon.debug pppd[3383]: sent [IPCP ConfReq id=0x1 ] 2009-06-14T01:06:33.219696Z [58426] castle daemon.debug pppd[3383]: rcvd [LCP DiscReq id=0x3 magic=0x4be2ee82] 2009-06-14T01:06:33.219848Z [58426] castle daemon.debug pppd[3383]: rcvd [IPCP ConfReq id=0x1 ] 2009-06-14T01:06:33.219970Z [58426] castle daemon.debug pppd[3383]: sent [IPCP ConfAck id=0x1 ] 2009-06-14T01:06:33.221313Z [58426] castle daemon.debug pppd[3383]: rcvd [IPCP ConfRej id=0x1 ] 2009-06-14T01:06:33.221527Z [58426] castle daemon.debug pppd[3383]: sent [IPCP ConfReq id=0x2 ] 2009-06-14T01:06:33.224243Z [58426] castle daemon.debug pppd[3383]: rcvd [IPCP ConfNak id=0x2 ] 2009-06-14T01:06:33.224426Z [58426] castle daemon.debug pppd[3383]: sent [IPCP ConfReq id=0x3 ] 2009-06-14T01:06:33.230255Z [58426] castle daemon.debug pppd[3383]: rcvd [IPCP ConfAck id=0x3 ] 2009-06-14T01:06:33.241485Z [58426] castle daemon.notice pppd[3383]: local IP address 174.144.157.234 2009-06-14T01:06:33.241729Z [58426] castle daemon.notice pppd[3383]: remote IP address 68.28.49.69 2009-06-14T01:06:33.241851Z [58426] castle daemon.notice pppd[3383]: primary DNS address 68.28.50.91 2009-06-14T01:06:33.241973Z [58426] castle daemon.notice pppd[3383]: secondary DNS address 68.28.58.92 2009-06-14T01:06:33.294616Z [58426] castle daemon.debug pppd[3383]: Script /etc/ppp/ip-up started (pid 3400) 2009-06-14T01:06:33.364318Z [58426] castle daemon.debug pppd[3383]: Script /etc/ppp/ip-up finished (pid 3400), status = 0x0 2009-06-14T01:06:33.428985Z [58426] castle local0.info dnsmasq[1190]: read /etc/hosts - 2 addresses 2009-06-14T01:06:33.429199Z [58426] castle local0.info dnsmasq[1190]: using nameserver 68.28.58.92#53 2009-06-14T01:06:33.429321Z [58426] castle local0.info dnsmasq[1190]: using nameserver 68.28.50.91#53 2009-06-14T01:06:33.512023Z [58427] castle user.info pubsubservice: [connectToService: 564]: We are connecting to the xmpp server. 2009-06-14T01:06:33.709045Z [58427] castle user.err LunaSysMgr: {LunaSysMgrJS} Info: Internet connection available: true, file:///var/usr/palm/applications/com.evernote.palm.app.evernote/index.html:0 2009-06-14T01:06:33.832458Z [58427] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStop: (com.palm.display-lock.timer) 2009-06-14T01:06:34.315734Z [58427] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStart: (com.palm.mail.imap.ImapTransport-imapsync-76965813944444) for 900000ms => true 2009-06-14T01:06:35.150085Z [58428] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStart: (com.palm.mail.imap.ImapTransport-imapsync-76965813944380) for 900000ms => true 2009-06-14T01:06:35.590240Z [58429] castle user.info pubsubservice: [attachSocketToMainLoop: 828]: Attached socket 12 to mainloop 2009-06-14T01:06:35.654998Z [58429] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStart: (com.palm.mail.imap.ImapTransport-imapsync-76965813944418) for 900000ms => true 2009-06-14T01:06:35.834350Z [58429] castle user.info powerd: POWERD-ALARM: alarmAddCalendar: (com.palm.taskScheduler (null) taskScheduler) at 06-14-2009 01:12:29 2009-06-14T01:06:36.308715Z [58429] castle user.warning powerd: POWERD-SUSPEND: IdleCheck can't sleep because because an activity is active: 2009-06-14T01:06:36.308929Z [58429] castle user.info powerd: POWERD-SUSPEND: Activities since wake: 2009-06-14T01:06:36.309051Z [58429] castle user.info powerd: POWERD-ACTIVITY: (com.palm.power.timeout_fired) for 5000 ms, expiry in -40 ms 2009-06-14T01:06:36.309173Z [58429] castle user.info powerd: POWERD-ACTIVITY: (com.palm.mail.imap.ImapTransport-imapsync-76965813944444) for 900000 ms, expiry in 898007 ms 2009-06-14T01:06:36.309295Z [58429] castle user.info powerd: POWERD-ACTIVITY: (com.palm.mail.imap.ImapTransport-imapsync-76965813944380) for 900000 ms, expiry in 898841 ms 2009-06-14T01:06:36.309417Z [58429] castle user.info powerd: POWERD-ACTIVITY: (com.palm.mail.imap.ImapTransport-imapsync-76965813944418) for 900000 ms, expiry in 899346 ms 2009-06-14T01:06:36.443817Z [58429] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStart: (com.palm.mail.imap.ImapTransport-imapsync-76965813944431) for 900000ms => true 2009-06-14T01:06:36.692962Z [58430] castle user.warning LunaSysService: getPreferences(): resultMap: [uaProf] -> [---, length 65] 2009-06-14T01:06:37.687469Z [58431] castle user.warning audiod: _pulseStatus: sink 1 (stream 8) opened 2009-06-14T01:06:37.750701Z [58431] castle user.info pubsubservice: [onConnect: 703]: We formed a connection with the xmpp server 2009-06-14T01:06:37.754455Z [58431] castle user.info powerd: POWERD-TIMEOUT: _power_timeout_clear (,(null),private) 2009-06-14T01:06:37.754638Z [58431] castle user.err powerd: LIBPOWERD: _timeout_delete: assertion `key != NULL' failed 2009-06-14T01:06:37.765106Z [58431] castle user.info powerd: POWERD-TIMEOUT: _power_timeout_set (,keepAliveTimer,wakeup) in 00:25:00 2009-06-14T01:06:38.657257Z [58432] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStop: (com.palm.mail.imap.ImapTransport-imapsync-76965813944444) 2009-06-14T01:06:40.097473Z [58433] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStop: (com.palm.mail.imap.ImapTransport-imapsync-76965813944418) 2009-06-14T01:06:40.160125Z [58433] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStop: (com.palm.mail.imap.ImapTransport-imapsync-76965813944431) 2009-06-14T01:06:40.240753Z [58433] castle user.warning audiod: _pulseStatus: pulse reports sink 1 (stream 8) closed 2009-06-14T01:06:40.448486Z [58433] castle user.warning audiod: closeSink: sink 1 processed closed after a delay 2009-06-14T01:06:41.211578Z [58434] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStop: (com.palm.mail.imap.ImapTransport-imapsync-76965813944380) 2009-06-14T01:06:55.260742Z [58448] castle user.info powerd: POWERD-TIMEOUT: _timeout_fire (com.palm.power,misc_timer-1113 => luna://com.palm.power/time/internalAlarmFired) 2009-06-14T01:06:55.260986Z [58448] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStart: (com.palm.power.timeout_fired) for 5000ms => true 2009-06-14T01:06:55.271881Z [58448] castle user.info powerd: POWERD-ALARM: Alarm ((null) (null) misc_timer) fired at Sun Jun 14 01:06:55 2009 2009-06-14T01:07:26.494781Z [58479] castle authpriv.info dropbear[3436]: Child connection from 10.1.1.129:50016 2009-06-14T01:07:30.782958Z [58484] castle authpriv.notice dropbear[3436]: pubkey auth succeeded for 'lhl' with key md5 a9:41:82:20:35:5b:30:04:f1:9f:93:e8:0b:e8:51:ee from 10.1.1.129:50016 2009-06-14T01:07:44.949462Z [58498] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStart: (com.palm.display-lock.timer) for 3000ms => true 2009-06-14T01:07:45.308532Z [58498] castle user.warning powerd: POWERD-SUSPEND: IdleCheck can't sleep because because an activity is active: 2009-06-14T01:07:45.308715Z [58498] castle user.info powerd: POWERD-SUSPEND: Activities since wake: 2009-06-14T01:07:45.308837Z [58498] castle user.info powerd: POWERD-ACTIVITY: (com.palm.power.timeout_fired) for 5000 ms, expiry in -45050 ms 2009-06-14T01:07:45.308959Z [58498] castle user.info powerd: POWERD-ACTIVITY: (com.palm.display-lock.timer) for 3000 ms, expiry in 2641 ms 2009-06-14T01:07:46.920806Z [58500] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStop: (com.palm.display-lock.timer) 2009-06-14T01:08:20.261016Z [58533] castle user.info powerd: POWERD-TIMEOUT: _timeout_fire (com.palm.power,misc_timer-1108 => luna://com.palm.power/time/internalAlarmFired) 2009-06-14T01:08:20.261260Z [58533] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStart: (com.palm.power.timeout_fired) for 5000ms => true 2009-06-14T01:08:20.270385Z [58533] castle user.info powerd: POWERD-ALARM: Alarm ((null) (null) misc_timer) fired at Sun Jun 14 01:08:20 2009 2009-06-14T01:08:20.408294Z [58533] castle user.warning powerd: POWERD-SUSPEND: IdleCheck can't sleep because because an activity is active: 2009-06-14T01:08:20.408477Z [58533] castle user.info powerd: POWERD-SUSPEND: Activities since wake: 2009-06-14T01:08:20.408599Z [58533] castle user.info powerd: POWERD-ACTIVITY: (com.palm.power.timeout_fired) for 5000 ms, expiry in 4850 ms 2009-06-14T01:08:25.308319Z [58538] castle user.info powerd: POWERD-SUSPEND: Activities since wake: 2009-06-14T01:08:25.308532Z [58538] castle user.info powerd: POWERD-ACTIVITY: (com.palm.power.timeout_fired) for 5000 ms, expiry in -50 ms 2009-06-14T01:08:26.258422Z [58539] castle user.info powerd: POWERD-TIMEOUT: _timeout_fire (com.palm.power,misc_timer-1116 => luna://com.palm.power/time/internalAlarmFired) 2009-06-14T01:08:26.258911Z [58539] castle user.info powerd: POWERD-ACTIVITY: PowerdActivityStart: (com.palm.power.timeout_fired) for 5000ms => true 2009-06-14T01:08:26.269805Z [58539] castle user.info powerd: POWERD-ALARM: Alarm ((null) (null) misc_timer) fired at Sun Jun 14 01:08:26 2009 2009-06-14T01:08:26.308258Z [58539] castle user.warning powerd: POWERD-SUSPEND: IdleCheck can't sleep because because an activity is active: 2009-06-14T01:08:26.308441Z [58539] castle user.info powerd: POWERD-SUSPEND: Activities since wake: 2009-06-14T01:08:26.308563Z [58539] castle user.info powerd: POWERD-ACTIVITY: (com.palm.power.timeout_fired) for 5000 ms, expiry in 4950 ms 2009-06-14T01:08:31.308227Z [58544] castle user.info powerd: POWERD-SUSPEND: Activities since wake: 2009-06-14T01:08:31.308441Z [58544] castle user.info powerd: POWERD-ACTIVITY: (com.palm.power.timeout_fired) for 5000 ms, expiry in -50 ms 2009-06-14T01:08:58.829925Z [58572] castle user.err LunaSysMgr: {LunaSysMgrJS} =========> looking for palmInitFramework175_7, file:///usr/palm/applications/com.palm.app.bluetooth/index.html:0 2009-06-14T01:08:58.831726Z [58572] castle user.err LunaSysMgr: {LunaSysMgrJS} =========> Calling palmInitFramework175_7, file:///usr/palm/applications/com.palm.app.bluetooth/index.html:0 2009-06-14T01:09:00.763305Z [58574] castle user.err LunaSysMgr: {LunaSysMgrJS} AppAssistant, file:///usr/palm/applications/com.palm.app.bluetooth/index.html:0 2009-06-14T01:09:02.231262Z [58575] castle user.err LunaSysMgr: {LunaSysMgrJS} Error: btServiceStart: BT service is now up (not an error), file:///usr/palm/applications/com.palm.app.bluetooth/index.html:0 2009-06-14T01:09:19.566558Z [58593] castle user.info powerd: BATTERY: (1181.800049mAh, 98%, 100%_ui, 29C, -175mA, 4099mV, authentic)