Warning: Can't synchronize with repository "(default)" (No changeset 96d22ec3fa3ef6de3ea8dc0d7d398adc9aa071cf in the repository). Look in the Trac log for more information.

Ticket #416 (closed defect: fixed)

Opened 5 years ago

Last modified 5 years ago

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:1 Changed 5 years ago by jluebbe

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:~# 

comment:2 Changed 5 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 5 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 5 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 5 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 5 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 5 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 5 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:9 Changed 5 years ago by ayers

  • Cc ayers@… added

comment:10 Changed 5 years ago by jluebbe

  • Status changed from reopened to in_testing

comment:11 Changed 5 years ago by jluebbe

This was a problem in idlenotifier.py, which should be fixed now.

comment:12 Changed 5 years ago by dos

  • Cc seba.dos1@… added

comment:13 Changed 5 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.

Note: See TracTickets for help on using tickets.