Ticket #416 (closed defect: fixed)
Parts of frameworkd stop working (oeventsd)
| Reported by: | daniel | Owned by: | jluebbe |
|---|---|---|---|
| Priority: | blocker | Milestone: | milestone5.5 |
| Component: | framework/oeventsd | Version: | |
| Keywords: | Cc: | ayers@…, seba.dos1@… |
Description
I usually trigger this if I have an incoming call and the remote side hangs up when the screen is going completely dark. The result is that the screen wont turn back on, the phone wont ring, LED will not indicate charging - in short oeventsd seems dead. I can - however - log in via USB. Logs don't show any errors, running frameworkd in a screen session doesn't show any errors, the log seems to indicate frameworkd is actually reacting to even the DBus calls that time out:
freesmartphone.org interactive command line
>>> usageiface.RequestResource("Display")
Traceback (most recent call last):
File "<console>", line 1, in <module>
File "/usr/lib/python2.6/site-packages/dbus/proxies.py", line 68, in __call__
return self._proxy_method(*args, **keywords)
File "/usr/lib/python2.6/site-packages/dbus/proxies.py", line 140, in __call__
**keywords)
File "/usr/lib/python2.6/site-packages/dbus/connection.py", line 622, in call_blocking
message, timeout)
DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
>>>
>>>
>>> usageiface.RequestResource("GPS")
Traceback (most recent call last):
File "<console>", line 1, in <module>
File "/usr/lib/python2.6/site-packages/dbus/proxies.py", line 140, in __call__
**keywords)
File "/usr/lib/python2.6/site-packages/dbus/connection.py", line 622, in call_blocking
message, timeout)
DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
>>> display.SetBrightness(100)
>>> gpsposition.GetPosition()
(0, 0, 0.0, 0.0, 0.0)
>>> gps
gps gpsaccuracy gpsposition gpssatellite gpstime
>>> gpstime.GetTime()
1240886058
>>> gpstime.GetTime()
1240886059
>>> gpstime.GetTime()
1240886060
>>> gpstime.GetTime()
1240886060
>>> usageiface.ReleaseResource("GPS")
>>>
Change History
comment:2 Changed 4 years ago by jluebbe
Hmm, i think i've found the source of the problem:
When the CPU resource is being released while the idle state is lock and a call is ending, the dbus reply is *not* sent from the status_ok_callback function in resource.py. The function object looks identical to the cases where it works...
I currently have no idea why it behaves this way. Maybe i'd need working eavesdrop for dbus, for me only the calls are visible, not the replies.
comment:3 Changed 4 years ago by mickey
- Priority changed from critical to blocker
I had a brief look into this issue, from what I can see here, starting with the moment, we hang up, no frameworkd-initiated DBus methods are actually getting sent -- dbus-monitor seems to confirm this.
Next step is scrutinizing the dbus-daemon itself, we may have hit an undocumented limit (maximum number of outstanding calls per client or what not)...
comment:4 Changed 4 years ago by daniel
I just tried with
<limit name="max_incomplete_connections">512</limit> <limit name="max_connections_per_user">512</limit> <limit name="max_replies_per_connection">50000</limit>
in system.conf to no avail. :-(
comment:5 Changed 4 years ago by mickey
Fwiw, reverting the idlenotifier.py to the one from MS5.1 fixes this problem. It's unclear to me why, then again I did not check the changes yet.
comment:6 Changed 4 years ago by daniel
Jan has made some interesting discoveries pointing to maybe a bug in libdbus itself. It seems the responses are getting received and queued, but the dispatcher stops handling the elements...
comment:7 Changed 4 years ago by mickey
- Status changed from new to closed
- Resolution set to fixed
I have worked around this now by reverting to an older version of the idlenotifier, then fixed the issue of CPU/Display resource reverting all timeouts (instead of one). I'm closing this very bug for now, but the underlying issue remains unfixed and may come and hunt us again at any time :( By any chance, we need to do a serious libdbus debugging session.
comment:8 Changed 4 years ago by daniel
- Status changed from closed to reopened
- Resolution fixed deleted
Not fixed yet (at least I'm still seeing similar issues) reopening to clarify
comment:11 Changed 4 years ago by jluebbe
This was a problem in idlenotifier.py, which should be fixed now.
comment:13 Changed 4 years ago by stefan
- Status changed from in_testing to closed
- Resolution set to fixed
The problem will no longer appear as we switched to the new fsousaged instead of ousaged. The problem is not, and will probably never, fixed in ousaged. Due to the switch it is no longer a problem for us.
I've tried to reproduce this with Daniel, when he calls me, i wait until the screen is off and then he hangs up. It behaves correctly: Screen turns back on.
When i call him, then wait until screen off and he hangs up, the screen stays of and oeventsd is completely dead. The rest of the framework is still functioning.
This log contains one short call without dimming and then waiting for screen off.
2009.05.01 16:43:14.6 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:43:15.5 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:43:16.6 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:43:17.6 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:43:18.6 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:43:19.6 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:43:19.735 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: Autogenerated prefixes for command u'ATD017621050247;\r\n': set([]) 2009.05.01 16:43:19.779 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: _readyToSend: watch timeout = None 2009.05.01 16:43:19.796 ogsmd DEBUG (<CallChannel via /dev/pts/4>: last communication with modem was 91 seconds ago. Sending EOF to wakeup) 2009.05.01 16:43:20.24 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: sending 18 bytes: 'ATD017621050247;\r\n' 2009.05.01 16:43:20.43 otimed DEBUG checking time sources 2009.05.01 16:43:20.57 otimed DEBUG no working time source 2009.05.01 16:43:20.75 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:43:20.99 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:20.117 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 70 bytes: '\r\n%CPI: 1,9,0,0,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:20.140 ogsmd.device INFO org.freesmartphone.GSM.Call.CallStatus: 1 outgoing {'status': 'outgoing', 'direction': 'outgoing', 'mode': 'voice', 'peer': '017621050247', 'line': 0} 2009.05.01 16:43:20.194 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: _readyToRead: watch timeout = 779 2009.05.01 16:43:20.211 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: got 6 bytes: '\r\nOK\r\n' 2009.05.01 16:43:20.242 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: COMPLETED 'ATD017621050247;' => ['OK'] AT RESPONSE FROM CHANNEL= ['OK'] 2009.05.01 16:43:20.264 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: _readyToSend: watch timeout = None 2009.05.01 16:43:20.298 oeventsd.fso_triggers INFO Receive CallStatus, status = outgoing 2009.05.01 16:43:20.322 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:20.363 oeventsd.fso_triggers DEBUG Trigger CallListContains(incoming) 2009.05.01 16:43:20.388 oeventsd.rule WARNING Untrigger for 'CallListContains(incoming)' called, but not yet triggered. Not untriggering 2009.05.01 16:43:20.405 oeventsd.fso_triggers INFO Receive CallStatus, status = outgoing 2009.05.01 16:43:20.437 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:20.452 oeventsd.fso_triggers DEBUG Trigger CallListContains(active) 2009.05.01 16:43:20.472 oeventsd.rule WARNING Untrigger for 'CallListContains(active)' called, but not yet triggered. Not untriggering 2009.05.01 16:43:20.499 oeventsd.fso_triggers INFO Receive CallStatus, status = outgoing 2009.05.01 16:43:20.522 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:20.544 oeventsd.trigger DEBUG trigger While CallStatus if Or(status == outgoing,status == active) then [OccupyResource(CPU)] 2009.05.01 16:43:20.581 oeventsd.action INFO call dbus method /org/freesmartphone/Usage RequestResource(('CPU',)) 2009.05.01 16:43:20.607 oeventsd.fso_triggers INFO Receive CallStatus, status = outgoing 2009.05.01 16:43:20.643 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:20.660 oeventsd.trigger DEBUG trigger While CallStatus if And(Or(status == outgoing,status == active),~(BTHeadsetIsConnected())) then [SetScenario(gsmhandset)] 2009.05.01 16:43:20.699 oeventsd INFO Set Audio Scenario gsmhandset 2009.05.01 16:43:20.727 oeventsd.action INFO call dbus method /org/freesmartphone/Device/Audio SetScenario(('gsmhandset',)) 2009.05.01 16:43:20.757 oeventsd.fso_triggers INFO Receive CallStatus, status = outgoing 2009.05.01 16:43:20.783 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:20.814 ophoned.gsm DEBUG call_status: 1 outgoing dbus.Dictionary({dbus.String(u'status'): dbus.String(u'outgoing', variant_level=1), dbus.String(u'peer'): dbus.String(u'017621050247', variant_level=1), dbus.String(u'direction'): dbus.String(u'outgoing', variant_level=1), dbus.String(u'line'): dbus.Int32(0, variant_level=1), dbus.String(u'mode'): dbus.String(u'voice', variant_level=1)}, signature=dbus.Signature('sv')) 2009.05.01 16:43:20.853 ophoned INFO CallCreated (<ophoned.gsm.Call at /org/freesmartphone/Phone/GSM/2 at 0x8982d0>) 2009.05.01 16:43:20.967 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:20.994 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 14 bytes: '\r\n%CPRI: 1,2\r\n' 2009.05.01 16:43:21.21 ogsmd.device INFO org.freesmartphone.GSM.Network.CypherStatus: enabled: unknown 2009.05.01 16:43:21.61 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:21.403 ousaged DEBUG Enabling CPU 2009.05.01 16:43:22.450 odeviced.audio INFO sound scenario gsmhandset user 2009.05.01 16:43:22.483 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:22.512 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 90 bytes: '\r\n%CSQ: 19, 99, 2\r\n\r\n%CPI: 1,3,0,0,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:22.553 ogsmd.device INFO org.freesmartphone.GSM.Network.SignalStrength: 86 2009.05.01 16:43:22.650 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:22.682 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 45 bytes: '%CCCN: 0,0,A10E0201000201103006810128840107\r\n' 2009.05.01 16:43:22.706 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:43:22.724 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: sending 10 bytes: 'AT%N0187\r\n' 2009.05.01 16:43:22.750 mppl.asyncworker DEBUG no elements in queue: starting idle task. 2009.05.01 16:43:22.777 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:43:22.795 mppl.asyncworker DEBUG no elements in queue: starting idle task. 2009.05.01 16:43:22.811 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 790 2009.05.01 16:43:22.829 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: got 57 bytes: '\r\nEXT: I\r\nBoth AEC and Noise reduction are active\r\n\r\nOK\r\n' 2009.05.01 16:43:22.847 ogsmd.modems.abstract.channel WARNING UNHANDLED INTERMEDIATE: EXT: I 2009.05.01 16:43:22.866 ogsmd.modems.abstract.channel WARNING UNHANDLED INTERMEDIATE: Both AEC and Noise reduction are active 2009.05.01 16:43:22.884 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: COMPLETED 'AT%N0187' => ['OK'] 2009.05.01 16:43:22.900 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:43:22.921 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:22.946 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 70 bytes: '\r\n%CPI: 1,4,0,1,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:22.974 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:43:22.992 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: sending 10 bytes: 'AT%N0187\r\n' 2009.05.01 16:43:23.13 oeventsd.action INFO method SetScenario responded: () 2009.05.01 16:43:23.34 odeviced.idlenotifier DEBUG state already active. ignoring request 2009.05.01 16:43:23.56 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 796 2009.05.01 16:43:23.73 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: got 57 bytes: '\r\nEXT: I\r\nBoth AEC and Noise reduction are active\r\n\r\nOK\r\n' 2009.05.01 16:43:23.97 ogsmd.modems.abstract.channel WARNING UNHANDLED INTERMEDIATE: EXT: I 2009.05.01 16:43:23.118 ogsmd.modems.abstract.channel WARNING UNHANDLED INTERMEDIATE: Both AEC and Noise reduction are active 2009.05.01 16:43:23.159 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: COMPLETED 'AT%N0187' => ['OK'] 2009.05.01 16:43:23.176 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:23.194 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 70 bytes: '\r\n%CPI: 1,5,1,1,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:23.217 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:43:23.235 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:43:23.250 mppl.asyncworker DEBUG got an element from the queue 2009.05.01 16:43:23.265 frameworkd.resource DEBUG processing command 'enable' for resource '<odeviced.idlenotifier.CpuResource at /org/freesmartphone/Device/CPU at 0x73a150>' 2009.05.01 16:43:23.281 frameworkd.resource INFO setting resource status for CPU from disabled to enabling 2009.05.01 16:43:23.296 odeviced.idlenotifier INFO allowed idle states now: set(['busy', 'lock', 'idle_prelock', 'idle', 'awake', 'idle_dim']) 2009.05.01 16:43:23.312 frameworkd.resource INFO setting resource status for CPU from enabling to enabled 2009.05.01 16:43:23.327 frameworkd.resource DEBUG resource now enabled. checking signal queue 2009.05.01 16:43:23.346 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:43:23.362 mppl.asyncworker DEBUG got an element from the queue 2009.05.01 16:43:23.382 ousaged INFO Enabled CPU in 2.0 seconds 2009.05.01 16:43:23.441 oeventsd.action INFO method RequestResource responded: () 2009.05.01 16:43:23.463 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:43:23.478 mppl.asyncworker DEBUG no more elements: stopping idle task. 2009.05.01 16:43:24.6 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:25.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:26.5 odeviced.helpers DEBUG (read '1' from '/sys/class/power_supply/battery/present') 2009.05.01 16:43:26.23 odeviced.helpers DEBUG (read '1' from '/sys/class/power_supply/battery/online') 2009.05.01 16:43:26.39 odeviced.helpers DEBUG (read '1' from '/sys/class/power_supply/battery/present') 2009.05.01 16:43:26.56 odeviced.helpers DEBUG (read '1' from '/sys/class/power_supply/battery/online') 2009.05.01 16:43:26.72 odeviced.helpers DEBUG (read '92' from '/sys/class/power_supply/battery/capacity') 2009.05.01 16:43:26.88 odeviced.kernel26 INFO capacity now 92 2009.05.01 16:43:26.109 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:26.239 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:26.257 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 70 bytes: '\r\n%CPI: 1,5,1,1,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:26.376 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:26.395 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 70 bytes: '\r\n%CPI: 1,2,1,1,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:27.6 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:28.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:29.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:30.6 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:31.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:31.612 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:31.629 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 70 bytes: '\r\n%CPI: 1,6,0,1,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:31.652 ogsmd.device INFO org.freesmartphone.GSM.Call.CallStatus: 1 active {'status': 'active', 'direction': 'outgoing', 'mode': 'voice', 'peer': '017621050247', 'line': 0} 2009.05.01 16:43:31.713 oeventsd.fso_triggers INFO Receive CallStatus, status = active 2009.05.01 16:43:31.737 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:31.762 oeventsd.fso_triggers DEBUG Trigger CallListContains(incoming) 2009.05.01 16:43:31.788 oeventsd.rule WARNING Untrigger for 'CallListContains(incoming)' called, but not yet triggered. Not untriggering 2009.05.01 16:43:31.814 oeventsd.fso_triggers INFO Receive CallStatus, status = active 2009.05.01 16:43:31.830 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:31.852 oeventsd.fso_triggers DEBUG Trigger CallListContains(active) 2009.05.01 16:43:31.873 oeventsd.trigger DEBUG trigger CallListContains(active) 2009.05.01 16:43:31.891 oeventsd.fso_triggers INFO Receive CallStatus, status = active 2009.05.01 16:43:31.917 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:31.942 oeventsd.fso_triggers INFO Receive CallStatus, status = active 2009.05.01 16:43:31.968 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:31.997 oeventsd.fso_triggers INFO Receive CallStatus, status = active 2009.05.01 16:43:32.22 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:32.50 ophoned.gsm DEBUG call_status: 1 active dbus.Dictionary({dbus.String(u'status'): dbus.String(u'active', variant_level=1), dbus.String(u'peer'): dbus.String(u'017621050247', variant_level=1), dbus.String(u'direction'): dbus.String(u'outgoing', variant_level=1), dbus.String(u'line'): dbus.Int32(0, variant_level=1), dbus.String(u'mode'): dbus.String(u'voice', variant_level=1)}, signature=dbus.Signature('sv')) 2009.05.01 16:43:32.87 odeviced.idlenotifier DEBUG state already active. ignoring request 2009.05.01 16:43:32.114 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:33.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:33.18 odeviced.idlenotifier INFO odeviced.idlenotifier state change to idle 2009.05.01 16:43:33.53 oeventsd.trigger DEBUG trigger DBusTrigger(org.freesmartphone.odeviced None.State) 2009.05.01 16:43:33.77 oeventsd.trigger DEBUG trigger on DBusTrigger(org.freesmartphone.odeviced None.State) if And() then Debug("dbus trigger test") 2009.05.01 16:43:33.107 oeventsd.action INFO DebugAction : dbus trigger test 2009.05.01 16:43:33.124 oeventsd.fso_triggers INFO Receive IdleState, status = idle 2009.05.01 16:43:33.147 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:43:33.174 oeventsd.trigger DEBUG trigger on IdleState if Or(status == busy,status == idle) then SetBrightness((90,)) 2009.05.01 16:43:33.243 oeventsd.action INFO call dbus method /org/freesmartphone/Device/Display/0 SetBrightness((90,)) 2009.05.01 16:43:33.263 oeventsd.fso_triggers INFO Receive IdleState, status = idle 2009.05.01 16:43:33.279 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:43:33.304 oeventsd.fso_triggers INFO Receive IdleState, status = idle 2009.05.01 16:43:33.327 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:43:33.461 oeventsd.action INFO method SetBrightness responded: () 2009.05.01 16:43:34.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:35.6 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:36.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:37.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:38.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:38.280 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:38.297 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 20 bytes: '\r\n%CSQ: 15, 99, 1\r\n' 2009.05.01 16:43:38.315 ogsmd.device INFO org.freesmartphone.GSM.Network.SignalStrength: 79 2009.05.01 16:43:39.6 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:40.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:41.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:42.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:43.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:43.240 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:43.258 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 72 bytes: '\r\n%CPI: 1,1,0,1,0,0,"017621050247",129,"00440061006E00690065006C",16,0\r\n' 2009.05.01 16:43:43.280 ogsmd.device INFO org.freesmartphone.GSM.Call.CallStatus: 1 release {'status': 'release'} 2009.05.01 16:43:43.335 oeventsd.fso_triggers INFO Receive CallStatus, status = release 2009.05.01 16:43:43.367 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:43.382 oeventsd.fso_triggers DEBUG Trigger CallListContains(incoming) 2009.05.01 16:43:43.403 oeventsd.rule WARNING Untrigger for 'CallListContains(incoming)' called, but not yet triggered. Not untriggering 2009.05.01 16:43:43.435 oeventsd.fso_triggers INFO Receive CallStatus, status = release 2009.05.01 16:43:43.461 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:43.482 oeventsd.fso_triggers DEBUG Trigger CallListContains(active) 2009.05.01 16:43:43.504 oeventsd.trigger DEBUG untrigger CallListContains(active) 2009.05.01 16:43:43.520 oeventsd.fso_triggers INFO Receive CallStatus, status = release 2009.05.01 16:43:43.542 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:43.564 oeventsd.trigger DEBUG untrigger While CallStatus if Or(status == outgoing,status == active) then [OccupyResource(CPU)] 2009.05.01 16:43:43.606 oeventsd.action INFO call dbus method /org/freesmartphone/Usage ReleaseResource(('CPU',)) 2009.05.01 16:43:43.641 oeventsd.fso_triggers INFO Receive CallStatus, status = release 2009.05.01 16:43:43.667 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:43.690 oeventsd.trigger DEBUG untrigger While CallStatus if And(Or(status == outgoing,status == active),~(BTHeadsetIsConnected())) then [SetScenario(gsmhandset)] 2009.05.01 16:43:43.718 oeventsd INFO Revert Audio Scenario to stereoout 2009.05.01 16:43:43.756 oeventsd.action INFO call dbus method /org/freesmartphone/Device/Audio SetScenario(('stereoout',)) 2009.05.01 16:43:43.781 oeventsd.fso_triggers INFO Receive CallStatus, status = release 2009.05.01 16:43:43.807 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:43.838 ophoned.gsm DEBUG call_status: 1 release dbus.Dictionary({dbus.String(u'status'): dbus.String(u'release', variant_level=1)}, signature=dbus.Signature('sv')) 2009.05.01 16:43:43.865 ophoned INFO CallReleased (<ophoned.gsm.Call at /org/freesmartphone/Phone/GSM/2 at 0x8982d0>) 2009.05.01 16:43:43.924 odeviced.idlenotifier INFO odeviced.idlenotifier state change to busy 2009.05.01 16:43:43.950 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:43.974 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 25 bytes: '\r\n%CPI: 1,7,0,0,,,,,,,0\r\n' 2009.05.01 16:43:44.3 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: _readyToRead: watch timeout = None 2009.05.01 16:43:44.29 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: got 14 bytes: '\r\nNO CARRIER\r\n' 2009.05.01 16:43:44.54 ogsmd WARNING CALLCHANNEL: UNHANDLED INTERMEDIATE: NO CARRIER 2009.05.01 16:43:44.76 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:44.110 oeventsd.trigger DEBUG trigger DBusTrigger(org.freesmartphone.odeviced None.State) 2009.05.01 16:43:44.126 oeventsd.trigger DEBUG trigger on DBusTrigger(org.freesmartphone.odeviced None.State) if And() then Debug("dbus trigger test") 2009.05.01 16:43:44.147 oeventsd.action INFO DebugAction : dbus trigger test 2009.05.01 16:43:44.168 oeventsd.fso_triggers INFO Receive IdleState, status = busy 2009.05.01 16:43:44.192 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:43:44.213 oeventsd.trigger DEBUG trigger on IdleState if Or(status == busy,status == idle) then SetBrightness((90,)) 2009.05.01 16:43:44.249 oeventsd.action INFO call dbus method /org/freesmartphone/Device/Display/0 SetBrightness((90,)) 2009.05.01 16:43:44.275 oeventsd.fso_triggers INFO Receive IdleState, status = busy 2009.05.01 16:43:44.302 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:43:44.324 oeventsd.fso_triggers INFO Receive IdleState, status = busy 2009.05.01 16:43:44.354 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:43:44.858 ousaged DEBUG Disabling CPU 2009.05.01 16:43:45.730 odeviced.audio INFO sound scenario stereoout user 2009.05.01 16:43:45.764 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:45.782 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:45.800 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 20 bytes: '\r\n%CSQ: 21, 99, 2\r\n' 2009.05.01 16:43:45.822 ogsmd.device INFO org.freesmartphone.GSM.Network.SignalStrength: 89 2009.05.01 16:43:45.878 oeventsd.action INFO method SetScenario responded: () 2009.05.01 16:43:45.902 mppl.asyncworker DEBUG no elements in queue: starting idle task. 2009.05.01 16:43:45.918 oeventsd.action INFO method SetBrightness responded: () 2009.05.01 16:43:45.934 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:43:45.949 mppl.asyncworker DEBUG got an element from the queue 2009.05.01 16:43:45.977 frameworkd.resource DEBUG processing command 'disable' for resource '<odeviced.idlenotifier.CpuResource at /org/freesmartphone/Device/CPU at 0x73a150>' 2009.05.01 16:43:45.994 frameworkd.resource INFO setting resource status for CPU from enabled to disabling 2009.05.01 16:43:46.9 odeviced.idlenotifier INFO allowed idle states now: set(['busy', 'lock', 'idle_prelock', 'idle', 'suspend', 'awake', 'idle_dim']) 2009.05.01 16:43:46.25 frameworkd.resource INFO setting resource status for CPU from disabling to disabled 2009.05.01 16:43:46.49 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:46.66 ousaged INFO Disabled CPU in 1.2 seconds 2009.05.01 16:43:46.106 oeventsd.action INFO method ReleaseResource responded: () 2009.05.01 16:43:47.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:47.43 frameworkd.kobject DEBUG Received kobject notification: 'change@/class/power_supply/battery\x00ACTION=change\x00DEVPATH=/class/power_supply/battery\x00SUBSYSTEM=power_supply\x00PHYSDEVPATH=/devices/platform/sc32440_fiq.0/gta02-hdq.0/bq27000-battery.0\x00PHYSDEVBUS=platform\x00PHYSDEVDRIVER=bq27000-battery\x00POWER_SUPPLY_NAME=battery\x00POWER_SUPPLY_TYPE=Battery\x00POWER_SUPPLY_STATUS=Charging\x00POWER_SUPPLY_HEALTH=Unknown\x00POWER_SUPPLY_VOLTAGE_NOW=4168000\x00POWER_SUPPLY_CURRENT_NOW=-135000\x00POWER_SUPPLY_CHARGE_FULL=1067073\x00POWER_SUPPLY_TEMP=318\x00POWER_SUPPLY_TECHNOLOGY=Li-ion\x00POWER_SUPPLY_PRESENT=1\x00POWER_SUPPLY_TIME_TO_EMPTY_NOW=3932100\x00POWER_SUPPLY_TIME_TO_FULL_NOW=3600\x00POWER_SUPPLY_CAPACITY=92\x00POWER_SUPPLY_ONLINE=1\x00SEQNUM=934\x00' 2009.05.01 16:43:47.76 odeviced.helpers DEBUG (read '1' from '/sys/class/power_supply/battery/present') 2009.05.01 16:43:47.93 odeviced.helpers DEBUG (read '1' from '/sys/class/power_supply/battery/online') 2009.05.01 16:43:47.108 odeviced.kernel26 DEBUG got property action 'change' from uevent for path '/class/power_supply/battery': {'SUBSYSTEM': 'power_supply', 'PHYSDEVDRIVER': 'bq27000-battery', 'PHYSDEVPATH': '/devices/platform/sc32440_fiq.0/gta02-hdq.0/bq27000-battery.0', 'POWER_SUPPLY_TIME_TO_FULL_NOW': '3600', 'DEVPATH': '/class/power_supply/battery', 'SEQNUM': '934', 'POWER_SUPPLY_HEALTH': 'Unknown', 'POWER_SUPPLY_TECHNOLOGY': 'Li-ion', 'POWER_SUPPLY_NAME': 'battery', 'POWER_SUPPLY_VOLTAGE_NOW': '4168000', 'ACTION': 'change', 'POWER_SUPPLY_TYPE': 'Battery', 'POWER_SUPPLY_STATUS': 'Charging', 'PHYSDEVBUS': 'platform', 'POWER_SUPPLY_ONLINE': '1', 'POWER_SUPPLY_TEMP': '318', 'POWER_SUPPLY_TIME_TO_EMPTY_NOW': '3932100', 'POWER_SUPPLY_PRESENT': '1', 'POWER_SUPPLY_CURRENT_NOW': '-135000', 'POWER_SUPPLY_CHARGE_FULL': '1067073', 'POWER_SUPPLY_CAPACITY': '92'} 2009.05.01 16:43:47.261 mppl.asyncworker DEBUG no elements in queue: starting idle task. 2009.05.01 16:43:47.278 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:43:47.294 mppl.asyncworker DEBUG got an element from the queue 2009.05.01 16:43:47.310 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:43:47.325 mppl.asyncworker DEBUG no more elements: stopping idle task. 2009.05.01 16:43:48.6 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:43:49.6 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:43:49.18 frameworkd.controller DEBUG alive and kicking 2009.05.01 16:43:49.714 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: _readyToSend: watch timeout = None 2009.05.01 16:43:49.744 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: sending 18 bytes: 'ATD017621050247;\r\n' 2009.05.01 16:43:49.824 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: _readyToRead: watch timeout = 815 2009.05.01 16:43:49.841 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: got 6 bytes: '\r\nOK\r\n' 2009.05.01 16:43:49.859 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: COMPLETED 'ATD017621050247;' => ['OK'] AT RESPONSE FROM CHANNEL= ['OK'] 2009.05.01 16:43:49.885 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:49.902 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 70 bytes: '\r\n%CPI: 1,9,0,0,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:49.925 ogsmd.device INFO org.freesmartphone.GSM.Call.CallStatus: 1 outgoing {'status': 'outgoing', 'direction': 'outgoing', 'mode': 'voice', 'peer': '017621050247', 'line': 0} 2009.05.01 16:43:49.974 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: _readyToSend: watch timeout = None 2009.05.01 16:43:49.999 oeventsd.fso_triggers INFO Receive CallStatus, status = outgoing 2009.05.01 16:43:50.26 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:50.47 oeventsd.fso_triggers DEBUG Trigger CallListContains(incoming) 2009.05.01 16:43:50.68 oeventsd.rule WARNING Untrigger for 'CallListContains(incoming)' called, but not yet triggered. Not untriggering 2009.05.01 16:43:50.111 oeventsd.fso_triggers INFO Receive CallStatus, status = outgoing 2009.05.01 16:43:50.128 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:50.152 oeventsd.fso_triggers DEBUG Trigger CallListContains(active) 2009.05.01 16:43:50.178 oeventsd.rule WARNING Untrigger for 'CallListContains(active)' called, but not yet triggered. Not untriggering 2009.05.01 16:43:50.204 oeventsd.fso_triggers INFO Receive CallStatus, status = outgoing 2009.05.01 16:43:50.227 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:50.251 oeventsd.trigger DEBUG trigger While CallStatus if Or(status == outgoing,status == active) then [OccupyResource(CPU)] 2009.05.01 16:43:50.293 oeventsd.action INFO call dbus method /org/freesmartphone/Usage RequestResource(('CPU',)) 2009.05.01 16:43:50.322 oeventsd.fso_triggers INFO Receive CallStatus, status = outgoing 2009.05.01 16:43:50.356 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:50.379 oeventsd.trigger DEBUG trigger While CallStatus if And(Or(status == outgoing,status == active),~(BTHeadsetIsConnected())) then [SetScenario(gsmhandset)] 2009.05.01 16:43:50.408 oeventsd INFO Set Audio Scenario gsmhandset 2009.05.01 16:43:50.453 oeventsd.action INFO call dbus method /org/freesmartphone/Device/Audio SetScenario(('gsmhandset',)) 2009.05.01 16:43:50.473 oeventsd.fso_triggers INFO Receive CallStatus, status = outgoing 2009.05.01 16:43:50.497 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:50.524 ophoned.gsm DEBUG call_status: 1 outgoing dbus.Dictionary({dbus.String(u'status'): dbus.String(u'outgoing', variant_level=1), dbus.String(u'peer'): dbus.String(u'017621050247', variant_level=1), dbus.String(u'direction'): dbus.String(u'outgoing', variant_level=1), dbus.String(u'line'): dbus.Int32(0, variant_level=1), dbus.String(u'mode'): dbus.String(u'voice', variant_level=1)}, signature=dbus.Signature('sv')) 2009.05.01 16:43:50.557 ophoned INFO CallCreated (<ophoned.gsm.Call at /org/freesmartphone/Phone/GSM/3 at 0x898350>) 2009.05.01 16:43:50.616 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:43:50.869 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:50.894 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 14 bytes: '\r\n%CPRI: 1,2\r\n' 2009.05.01 16:43:50.921 ogsmd.device INFO org.freesmartphone.GSM.Network.CypherStatus: enabled: unknown 2009.05.01 16:43:51.131 ousaged DEBUG Enabling CPU 2009.05.01 16:43:52.201 odeviced.audio INFO sound scenario gsmhandset user 2009.05.01 16:43:52.245 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:52.280 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 115 bytes: '\r\n%CPI: 1,3,0,0,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n%CCCN: 0,0,A10E0201000201103006810128840107\r\n' 2009.05.01 16:43:52.328 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:43:52.346 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: sending 10 bytes: 'AT%N0187\r\n' 2009.05.01 16:43:52.380 mppl.asyncworker DEBUG no elements in queue: starting idle task. 2009.05.01 16:43:52.405 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:43:52.423 mppl.asyncworker DEBUG no elements in queue: starting idle task. 2009.05.01 16:43:52.439 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 826 2009.05.01 16:43:52.457 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: got 57 bytes: '\r\nEXT: I\r\nBoth AEC and Noise reduction are active\r\n\r\nOK\r\n' 2009.05.01 16:43:52.475 ogsmd.modems.abstract.channel WARNING UNHANDLED INTERMEDIATE: EXT: I 2009.05.01 16:43:52.494 ogsmd.modems.abstract.channel WARNING UNHANDLED INTERMEDIATE: Both AEC and Noise reduction are active 2009.05.01 16:43:52.520 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: COMPLETED 'AT%N0187' => ['OK'] 2009.05.01 16:43:52.537 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:52.554 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 70 bytes: '\r\n%CPI: 1,4,0,1,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:52.581 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:43:52.599 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: sending 10 bytes: 'AT%N0187\r\n' 2009.05.01 16:43:52.618 oeventsd.action INFO method SetScenario responded: () 2009.05.01 16:43:52.641 odeviced.idlenotifier DEBUG state already active. ignoring request 2009.05.01 16:43:52.663 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 831 2009.05.01 16:43:52.680 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: got 57 bytes: '\r\nEXT: I\r\nBoth AEC and Noise reduction are active\r\n\r\nOK\r\n' 2009.05.01 16:43:52.730 ogsmd.modems.abstract.channel WARNING UNHANDLED INTERMEDIATE: EXT: I 2009.05.01 16:43:52.749 ogsmd.modems.abstract.channel WARNING UNHANDLED INTERMEDIATE: Both AEC and Noise reduction are active 2009.05.01 16:43:52.767 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: COMPLETED 'AT%N0187' => ['OK'] 2009.05.01 16:43:52.783 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:52.800 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 70 bytes: '\r\n%CPI: 1,5,1,1,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:52.824 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:43:52.843 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:43:52.858 mppl.asyncworker DEBUG got an element from the queue 2009.05.01 16:43:52.873 frameworkd.resource DEBUG processing command 'enable' for resource '<odeviced.idlenotifier.CpuResource at /org/freesmartphone/Device/CPU at 0x73a150>' 2009.05.01 16:43:52.889 frameworkd.resource INFO setting resource status for CPU from disabled to enabling 2009.05.01 16:43:52.904 odeviced.idlenotifier INFO allowed idle states now: set(['busy', 'lock', 'idle_prelock', 'idle', 'awake', 'idle_dim']) 2009.05.01 16:43:52.920 frameworkd.resource INFO setting resource status for CPU from enabling to enabled 2009.05.01 16:43:52.935 frameworkd.resource DEBUG resource now enabled. checking signal queue 2009.05.01 16:43:52.955 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:43:52.971 mppl.asyncworker DEBUG got an element from the queue 2009.05.01 16:43:52.991 ousaged INFO Enabled CPU in 1.8 seconds 2009.05.01 16:43:53.32 oeventsd.action INFO method RequestResource responded: () 2009.05.01 16:43:53.54 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:43:53.68 mppl.asyncworker DEBUG no more elements: stopping idle task. 2009.05.01 16:43:54.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:55.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:55.979 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:55.997 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 70 bytes: '\r\n%CPI: 1,5,1,1,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:56.23 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:56.99 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:56.117 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 70 bytes: '\r\n%CPI: 1,2,1,1,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:57.6 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:57.114 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:57.131 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 20 bytes: '\r\n%CSQ: 16, 99, 1\r\n' 2009.05.01 16:43:57.150 ogsmd.device INFO org.freesmartphone.GSM.Network.SignalStrength: 81 2009.05.01 16:43:58.6 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:59.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:43:59.617 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:43:59.634 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 70 bytes: '\r\n%CPI: 1,6,0,1,0,0,"017621050247",129,"00440061006E00690065006C",,0\r\n' 2009.05.01 16:43:59.657 ogsmd.device INFO org.freesmartphone.GSM.Call.CallStatus: 1 active {'status': 'active', 'direction': 'outgoing', 'mode': 'voice', 'peer': '017621050247', 'line': 0} 2009.05.01 16:43:59.718 oeventsd.fso_triggers INFO Receive CallStatus, status = active 2009.05.01 16:43:59.742 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:59.762 oeventsd.fso_triggers DEBUG Trigger CallListContains(incoming) 2009.05.01 16:43:59.783 oeventsd.rule WARNING Untrigger for 'CallListContains(incoming)' called, but not yet triggered. Not untriggering 2009.05.01 16:43:59.809 oeventsd.fso_triggers INFO Receive CallStatus, status = active 2009.05.01 16:43:59.825 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:59.847 oeventsd.fso_triggers DEBUG Trigger CallListContains(active) 2009.05.01 16:43:59.868 oeventsd.trigger DEBUG trigger CallListContains(active) 2009.05.01 16:43:59.886 oeventsd.fso_triggers INFO Receive CallStatus, status = active 2009.05.01 16:43:59.919 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:59.935 oeventsd.fso_triggers INFO Receive CallStatus, status = active 2009.05.01 16:43:59.972 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:43:59.992 oeventsd.fso_triggers INFO Receive CallStatus, status = active 2009.05.01 16:44:00.26 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:44:00.102 ophoned.gsm DEBUG call_status: 1 active dbus.Dictionary({dbus.String(u'status'): dbus.String(u'active', variant_level=1), dbus.String(u'peer'): dbus.String(u'017621050247', variant_level=1), dbus.String(u'direction'): dbus.String(u'outgoing', variant_level=1), dbus.String(u'line'): dbus.Int32(0, variant_level=1), dbus.String(u'mode'): dbus.String(u'voice', variant_level=1)}, signature=dbus.Signature('sv')) 2009.05.01 16:44:00.139 odeviced.idlenotifier DEBUG state already active. ignoring request 2009.05.01 16:44:00.169 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:01.6 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:02.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:03.6 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:03.21 odeviced.idlenotifier INFO odeviced.idlenotifier state change to idle 2009.05.01 16:44:03.62 oeventsd.trigger DEBUG trigger DBusTrigger(org.freesmartphone.odeviced None.State) 2009.05.01 16:44:03.78 oeventsd.trigger DEBUG trigger on DBusTrigger(org.freesmartphone.odeviced None.State) if And() then Debug("dbus trigger test") 2009.05.01 16:44:03.95 oeventsd.action INFO DebugAction : dbus trigger test 2009.05.01 16:44:03.111 oeventsd.fso_triggers INFO Receive IdleState, status = idle 2009.05.01 16:44:03.127 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:44:03.144 oeventsd.trigger DEBUG trigger on IdleState if Or(status == busy,status == idle) then SetBrightness((90,)) 2009.05.01 16:44:03.177 oeventsd.action INFO call dbus method /org/freesmartphone/Device/Display/0 SetBrightness((90,)) 2009.05.01 16:44:03.195 oeventsd.fso_triggers INFO Receive IdleState, status = idle 2009.05.01 16:44:03.212 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:44:03.229 oeventsd.fso_triggers INFO Receive IdleState, status = idle 2009.05.01 16:44:03.245 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:44:03.333 oeventsd.action INFO method SetBrightness responded: () 2009.05.01 16:44:04.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:05.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:06.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:07.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:08.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:09.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:10.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:11.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:12.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:13.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:14.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:15.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:16.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:17.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:18.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:19.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:20.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:21.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:22.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:23.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:23.21 odeviced.idlenotifier INFO odeviced.idlenotifier state change to idle_dim 2009.05.01 16:44:23.62 oeventsd.trigger DEBUG trigger DBusTrigger(org.freesmartphone.odeviced None.State) 2009.05.01 16:44:23.77 oeventsd.trigger DEBUG trigger on DBusTrigger(org.freesmartphone.odeviced None.State) if And() then Debug("dbus trigger test") 2009.05.01 16:44:23.93 oeventsd.action INFO DebugAction : dbus trigger test 2009.05.01 16:44:23.109 oeventsd.fso_triggers INFO Receive IdleState, status = idle_dim 2009.05.01 16:44:23.125 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:44:23.143 oeventsd.fso_triggers INFO Receive IdleState, status = idle_dim 2009.05.01 16:44:23.160 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:44:23.175 oeventsd.trigger DEBUG trigger on IdleState if status == idle_dim then SetBrightness((20,)) 2009.05.01 16:44:23.204 oeventsd.action INFO call dbus method /org/freesmartphone/Device/Display/0 SetBrightness((20,)) 2009.05.01 16:44:23.222 oeventsd.fso_triggers INFO Receive IdleState, status = idle_dim 2009.05.01 16:44:23.238 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:44:23.318 odeviced.helpers DEBUG (writing '51' to '/sys/class/backlight/gta02-bl/brightness') 2009.05.01 16:44:23.400 oeventsd.action INFO method SetBrightness responded: () 2009.05.01 16:44:24.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:25.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:26.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:27.24 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:28.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:29.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:30.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:31.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:32.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:33.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:34.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:35.6 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:35.21 odeviced.idlenotifier INFO odeviced.idlenotifier state change to idle_prelock 2009.05.01 16:44:35.62 oeventsd.trigger DEBUG trigger DBusTrigger(org.freesmartphone.odeviced None.State) 2009.05.01 16:44:35.77 oeventsd.trigger DEBUG trigger on DBusTrigger(org.freesmartphone.odeviced None.State) if And() then Debug("dbus trigger test") 2009.05.01 16:44:35.93 oeventsd.action INFO DebugAction : dbus trigger test 2009.05.01 16:44:35.109 oeventsd.fso_triggers INFO Receive IdleState, status = idle_prelock 2009.05.01 16:44:35.125 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:44:35.143 oeventsd.fso_triggers INFO Receive IdleState, status = idle_prelock 2009.05.01 16:44:35.159 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:44:35.176 oeventsd.fso_triggers INFO Receive IdleState, status = idle_prelock 2009.05.01 16:44:35.192 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:44:35.208 oeventsd.trigger DEBUG trigger on IdleState if status == idle_prelock then SetBrightness((0,)) 2009.05.01 16:44:35.256 oeventsd.action INFO call dbus method /org/freesmartphone/Device/Display/0 SetBrightness((0,)) 2009.05.01 16:44:35.336 odeviced.helpers DEBUG (writing '0' to '/sys/class/backlight/gta02-bl/brightness') 2009.05.01 16:44:35.413 odeviced.kernel26 DEBUG issuing ioctl( FBIOBLANK, FB_BLANK_POWERDOWN ) 2009.05.01 16:44:35.498 oeventsd.action INFO method SetBrightness responded: () 2009.05.01 16:44:36.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:37.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:37.22 odeviced.idlenotifier INFO odeviced.idlenotifier state change to lock 2009.05.01 16:44:37.74 oeventsd.trigger DEBUG trigger DBusTrigger(org.freesmartphone.odeviced None.State) 2009.05.01 16:44:37.102 oeventsd.trigger DEBUG trigger on DBusTrigger(org.freesmartphone.odeviced None.State) if And() then Debug("dbus trigger test") 2009.05.01 16:44:37.119 oeventsd.action INFO DebugAction : dbus trigger test 2009.05.01 16:44:37.143 oeventsd.fso_triggers INFO Receive IdleState, status = lock 2009.05.01 16:44:37.160 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:44:37.185 oeventsd.fso_triggers INFO Receive IdleState, status = lock 2009.05.01 16:44:37.207 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:44:37.230 oeventsd.fso_triggers INFO Receive IdleState, status = lock 2009.05.01 16:44:37.250 oeventsd.trigger DEBUG trigger IdleState 2009.05.01 16:44:37.330 frameworkd.kobject DEBUG Received kobject notification: 'change@/class/power_supply/battery\x00ACTION=change\x00DEVPATH=/class/power_supply/battery\x00SUBSYSTEM=power_supply\x00PHYSDEVPATH=/devices/platform/sc32440_fiq.0/gta02-hdq.0/bq27000-battery.0\x00PHYSDEVBUS=platform\x00PHYSDEVDRIVER=bq27000-battery\x00POWER_SUPPLY_NAME=battery\x00POWER_SUPPLY_TYPE=Battery\x00POWER_SUPPLY_STATUS=Charging\x00POWER_SUPPLY_HEALTH=Unknown\x00POWER_SUPPLY_VOLTAGE_NOW=4173000\x00POWER_SUPPLY_CURRENT_NOW=-219375\x00POWER_SUPPLY_CHARGE_FULL=1067073\x00POWER_SUPPLY_TEMP=321\x00POWER_SUPPLY_TECHNOLOGY=Li-ion\x00POWER_SUPPLY_PRESENT=1\x00POWER_SUPPLY_TIME_TO_EMPTY_NOW=3932100\x00POWER_SUPPLY_TIME_TO_FULL_NOW=2160\x00POWER_SUPPLY_CAPACITY=92\x00POWER_SUPPLY_ONLINE=1\x00SEQNUM=935\x00' 2009.05.01 16:44:37.371 odeviced.helpers DEBUG (read '1' from '/sys/class/power_supply/battery/present') 2009.05.01 16:44:37.398 odeviced.helpers DEBUG (read '1' from '/sys/class/power_supply/battery/online') 2009.05.01 16:44:37.423 odeviced.kernel26 DEBUG got property action 'change' from uevent for path '/class/power_supply/battery': {'SUBSYSTEM': 'power_supply', 'PHYSDEVDRIVER': 'bq27000-battery', 'PHYSDEVPATH': '/devices/platform/sc32440_fiq.0/gta02-hdq.0/bq27000-battery.0', 'POWER_SUPPLY_TIME_TO_FULL_NOW': '2160', 'DEVPATH': '/class/power_supply/battery', 'SEQNUM': '935', 'POWER_SUPPLY_HEALTH': 'Unknown', 'POWER_SUPPLY_TECHNOLOGY': 'Li-ion', 'POWER_SUPPLY_NAME': 'battery', 'POWER_SUPPLY_VOLTAGE_NOW': '4173000', 'ACTION': 'change', 'POWER_SUPPLY_TYPE': 'Battery', 'POWER_SUPPLY_STATUS': 'Charging', 'PHYSDEVBUS': 'platform', 'POWER_SUPPLY_ONLINE': '1', 'POWER_SUPPLY_TEMP': '321', 'POWER_SUPPLY_TIME_TO_EMPTY_NOW': '3932100', 'POWER_SUPPLY_PRESENT': '1', 'POWER_SUPPLY_CURRENT_NOW': '-219375', 'POWER_SUPPLY_CHARGE_FULL': '1067073', 'POWER_SUPPLY_CAPACITY': '92'} 2009.05.01 16:44:38.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:39.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:40.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:41.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:42.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:43.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:44.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:44.203 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:44:44.220 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 72 bytes: '\r\n%CPI: 1,1,0,1,0,0,"017621050247",129,"00440061006E00690065006C",16,0\r\n' 2009.05.01 16:44:44.249 ogsmd.device INFO org.freesmartphone.GSM.Call.CallStatus: 1 release {'status': 'release'} 2009.05.01 16:44:44.303 oeventsd.fso_triggers INFO Receive CallStatus, status = release 2009.05.01 16:44:44.327 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:44:44.367 oeventsd.fso_triggers DEBUG Trigger CallListContains(incoming) 2009.05.01 16:44:44.392 oeventsd.rule WARNING Untrigger for 'CallListContains(incoming)' called, but not yet triggered. Not untriggering 2009.05.01 16:44:44.419 oeventsd.fso_triggers INFO Receive CallStatus, status = release 2009.05.01 16:44:44.452 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:44:44.477 oeventsd.fso_triggers DEBUG Trigger CallListContains(active) 2009.05.01 16:44:44.498 oeventsd.trigger DEBUG untrigger CallListContains(active) 2009.05.01 16:44:44.514 oeventsd.fso_triggers INFO Receive CallStatus, status = release 2009.05.01 16:44:44.551 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:44:44.568 oeventsd.trigger DEBUG untrigger While CallStatus if Or(status == outgoing,status == active) then [OccupyResource(CPU)] 2009.05.01 16:44:44.613 oeventsd.action INFO call dbus method /org/freesmartphone/Usage ReleaseResource(('CPU',)) 2009.05.01 16:44:44.632 oeventsd.fso_triggers INFO Receive CallStatus, status = release 2009.05.01 16:44:44.668 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:44:44.686 oeventsd.trigger DEBUG untrigger While CallStatus if And(Or(status == outgoing,status == active),~(BTHeadsetIsConnected())) then [SetScenario(gsmhandset)] 2009.05.01 16:44:44.725 oeventsd INFO Revert Audio Scenario to stereoout 2009.05.01 16:44:44.753 oeventsd.action INFO call dbus method /org/freesmartphone/Device/Audio SetScenario(('stereoout',)) 2009.05.01 16:44:44.781 oeventsd.fso_triggers INFO Receive CallStatus, status = release 2009.05.01 16:44:44.808 oeventsd.trigger DEBUG trigger CallStatus 2009.05.01 16:44:44.840 ophoned.gsm DEBUG call_status: 1 release dbus.Dictionary({dbus.String(u'status'): dbus.String(u'release', variant_level=1)}, signature=dbus.Signature('sv')) 2009.05.01 16:44:44.860 ophoned INFO CallReleased (<ophoned.gsm.Call at /org/freesmartphone/Phone/GSM/3 at 0x898350>) 2009.05.01 16:44:44.894 odeviced.idlenotifier INFO odeviced.idlenotifier state change to busy 2009.05.01 16:44:44.933 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:44:44.959 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 25 bytes: '\r\n%CPI: 1,7,0,0,,,,,,,0\r\n' 2009.05.01 16:44:44.978 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: _readyToRead: watch timeout = None 2009.05.01 16:44:45.16 ogsmd.channel DEBUG <CallChannel via /dev/pts/4>: got 14 bytes: '\r\nNO CARRIER\r\n' 2009.05.01 16:44:45.33 ogsmd WARNING CALLCHANNEL: UNHANDLED INTERMEDIATE: NO CARRIER 2009.05.01 16:44:45.65 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:46.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:46.95 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:44:46.112 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 26 bytes: '\r\n+CREG: 1,"27E4","AC72"\r\n' 2009.05.01 16:44:46.140 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:44:46.158 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: sending 8 bytes: 'AT+CSQ\r\n' 2009.05.01 16:44:46.190 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 848 2009.05.01 16:44:46.208 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: got 22 bytes: '\r\n+CSQ: 13,99 \r\n\r\nOK\r\n' 2009.05.01 16:44:46.228 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: COMPLETED 'AT+CSQ' => ['+CSQ: 13,99 ', 'OK'] 2009.05.01 16:44:46.248 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:44:46.266 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: sending 10 bytes: 'AT+CREG?\r\n' 2009.05.01 16:44:46.299 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 851 2009.05.01 16:44:46.316 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: got 20 bytes: '\r\n+CREG: 0,1\r\n\r\nOK\r\n' 2009.05.01 16:44:46.336 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: COMPLETED 'AT+CREG?' => ['+CREG: 0,1', 'OK'] 2009.05.01 16:44:46.372 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:44:46.390 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: sending 26 bytes: 'AT+CREG=2;+CREG?;+CREG=0\r\n' 2009.05.01 16:44:46.429 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 854 2009.05.01 16:44:46.446 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: got 34 bytes: '\r\n+CREG: 2,1,"27E4","AC72"\r\n\r\nOK\r\n' 2009.05.01 16:44:46.467 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: COMPLETED 'AT+CREG=2;+CREG?;+CREG=0' => ['+CREG: 2,1,"27E4","AC72"', 'OK'] 2009.05.01 16:44:46.507 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:44:46.525 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: sending 37 bytes: 'AT+COPS=3,0;+COPS?;+COPS=3,2;+COPS?\r\n' 2009.05.01 16:44:46.565 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 857 2009.05.01 16:44:46.584 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: got 52 bytes: '\r\n+COPS: 0,0,"o2 - de"\r\n\r\n+COPS: 0,2,"26207"\r\n\r\nOK\r\n' 2009.05.01 16:44:46.607 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: COMPLETED 'AT+COPS=3,0;+COPS?;+COPS=3,2;+COPS?' => ['+COPS: 0,0,"o2 - de"', '+COPS: 0,2,"26207"', 'OK'] 2009.05.01 16:44:46.628 ogsmd.device INFO org.freesmartphone.GSM.Network.Status: {'strength': 75, 'cid': u'AC72', 'registration': 'home', 'lac': u'27E4', 'act': 'GSM', 'code': u'26207', 'mode': 'automatic', 'provider': u'o2 - de'} 2009.05.01 16:44:46.684 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:44:46.732 otimed DEBUG GSM: MCC=262 MNC=07 2009.05.01 16:44:46.810 otimed DEBUG GSM: ISO-Code DE 2009.05.01 16:44:46.842 otimed DEBUG GSM: determining time zone (isocode=DE offset=None) 2009.05.01 16:44:46.963 otimed DEBUG GSM: found zone ['DE', '+5230+01322', 'Europe/Berlin'] 2009.05.01 16:44:47.163 otimed INFO GSM: timezone 'Europe/Berlin' 2009.05.01 16:44:47.212 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:48.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:49.6 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:49.21 frameworkd.controller DEBUG alive and kicking 2009.05.01 16:44:50.3 otimed DEBUG checking time sources 2009.05.01 16:44:50.18 otimed DEBUG no working time source 2009.05.01 16:44:50.35 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:51.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:52.6 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:44:53.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:44:54.6 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:44:55.12 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:44:56.6 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:44:56.807 mppl.asyncworker DEBUG no elements in queue: starting idle task. 2009.05.01 16:44:56.824 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:44:56.840 mppl.asyncworker DEBUG got an element from the queue 2009.05.01 16:44:56.856 odeviced.input INFO name AUX pressed 0 2009.05.01 16:44:56.895 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:44:56.910 mppl.asyncworker DEBUG no more elements: stopping idle task. 2009.05.01 16:44:57.5 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:44:57.45 mppl.asyncworker DEBUG no elements in queue: starting idle task. 2009.05.01 16:44:57.62 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:44:57.78 mppl.asyncworker DEBUG got an element from the queue 2009.05.01 16:44:57.93 odeviced.input INFO name AUX released 0 2009.05.01 16:44:57.131 mppl.asyncworker DEBUG _processElement() 2009.05.01 16:44:57.146 mppl.asyncworker DEBUG no more elements: stopping idle task. 2009.05.01 16:44:58.7 odeviced.idlenotifier DEBUG active = True 2009.05.01 16:44:59.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:45:00.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:45:01.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:45:02.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:45:02.101 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: _readyToRead: watch timeout = None 2009.05.01 16:45:02.118 ogsmd.channel DEBUG <UnsolicitedResponseChannel via /dev/pts/3>: got 26 bytes: '\r\n+CREG: 1,"27E4","5E52"\r\n' 2009.05.01 16:45:02.144 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:45:02.162 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: sending 8 bytes: 'AT+CSQ\r\n' 2009.05.01 16:45:02.195 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 865 2009.05.01 16:45:02.212 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: got 22 bytes: '\r\n+CSQ: 10,99 \r\n\r\nOK\r\n' 2009.05.01 16:45:02.232 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: COMPLETED 'AT+CSQ' => ['+CSQ: 10,99 ', 'OK'] 2009.05.01 16:45:02.253 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:45:02.270 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: sending 10 bytes: 'AT+CREG?\r\n' 2009.05.01 16:45:02.304 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 868 2009.05.01 16:45:02.323 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: got 20 bytes: '\r\n+CREG: 0,1\r\n\r\nOK\r\n' 2009.05.01 16:45:02.342 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: COMPLETED 'AT+CREG?' => ['+CREG: 0,1', 'OK'] 2009.05.01 16:45:02.370 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:45:02.398 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: sending 26 bytes: 'AT+CREG=2;+CREG?;+CREG=0\r\n' 2009.05.01 16:45:02.442 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 871 2009.05.01 16:45:02.458 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: got 34 bytes: '\r\n+CREG: 2,1,"27E4","5E52"\r\n\r\nOK\r\n' 2009.05.01 16:45:02.479 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: COMPLETED 'AT+CREG=2;+CREG?;+CREG=0' => ['+CREG: 2,1,"27E4","5E52"', 'OK'] 2009.05.01 16:45:02.502 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:45:02.519 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: sending 37 bytes: 'AT+COPS=3,0;+COPS?;+COPS=3,2;+COPS?\r\n' 2009.05.01 16:45:02.559 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToRead: watch timeout = 874 2009.05.01 16:45:02.580 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: got 52 bytes: '\r\n+COPS: 0,0,"o2 - de"\r\n\r\n+COPS: 0,2,"26207"\r\n\r\nOK\r\n' 2009.05.01 16:45:02.603 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: COMPLETED 'AT+COPS=3,0;+COPS?;+COPS=3,2;+COPS?' => ['+COPS: 0,0,"o2 - de"', '+COPS: 0,2,"26207"', 'OK'] 2009.05.01 16:45:02.623 ogsmd.device INFO org.freesmartphone.GSM.Network.Status: {'strength': 67, 'cid': u'5E52', 'registration': 'home', 'lac': u'27E4', 'act': 'GSM', 'code': u'26207', 'mode': 'automatic', 'provider': u'o2 - de'} 2009.05.01 16:45:02.679 ogsmd.channel DEBUG <MiscChannel via /dev/pts/2>: _readyToSend: watch timeout = None 2009.05.01 16:45:02.725 otimed DEBUG GSM: MCC=262 MNC=07 2009.05.01 16:45:02.790 otimed DEBUG GSM: ISO-Code DE 2009.05.01 16:45:02.807 otimed DEBUG GSM: determining time zone (isocode=DE offset=None) 2009.05.01 16:45:02.895 otimed DEBUG GSM: found zone ['DE', '+5230+01322', 'Europe/Berlin'] 2009.05.01 16:45:03.4 otimed INFO GSM: timezone 'Europe/Berlin' 2009.05.01 16:45:03.33 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:45:04.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:45:05.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:45:06.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:45:07.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:45:08.5 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:45:08.22 odeviced.idlenotifier INFO odeviced.idlenotifier state change to idle 2009.05.01 16:45:09.18 odeviced.idlenotifier DEBUG active = False 2009.05.01 16:45:10.5 odeviced.idlenotifier DEBUG active = False ^Cctrl-c: exiting. 2009.05.01 16:45:10.284 frameworkd.controller INFO shutting down... 2009.05.01 16:45:10.304 odeviced.helpers DEBUG (writing 'none' to '/sys/class/leds/gta02-power:orange/trigger') 2009.05.01 16:45:10.322 odeviced.helpers DEBUG (writing '0' to '/sys/class/leds/gta02-power:orange/brightness') 2009.05.01 16:45:10.341 odeviced.helpers DEBUG (writing 'none' to '/sys/class/leds/neo1973:vibrator/trigger') 2009.05.01 16:45:10.365 odeviced.helpers DEBUG (writing '0' to '/sys/class/leds/neo1973:vibrator/brightness') 2009.05.01 16:45:10.384 mppl.asyncworker DEBUG no elements in queue: starting idle task. 2009.05.01 16:45:10.399 odeviced.helpers DEBUG (writing 'none' to '/sys/class/leds/gta02-power:blue/trigger') 2009.05.01 16:45:10.416 odeviced.helpers DEBUG (writing '0' to '/sys/class/leds/gta02-power:blue/brightness') 2009.05.01 16:45:10.433 odeviced.helpers DEBUG (writing 'none' to '/sys/class/leds/gta02-aux:red/trigger') 2009.05.01 16:45:10.450 odeviced.helpers DEBUG (writing '0' to '/sys/class/leds/gta02-aux:red/brightness') 2009.05.01 16:45:10.470 mppl.asyncworker DEBUG no elements in queue: starting idle task. root@om-gta02:~#