Closed Bug 713301 Opened 13 years ago Closed 12 years ago

Audio (and other services) not initialized in emulator

Categories

(Core :: Audio/Video, defect)

ARM
Gonk (Firefox OS)
defect
Not set
normal

Tracking

()

RESOLVED FIXED

People

(Reporter: cjones, Assigned: cjones)

References

Details

Attachments

(1 file)

The android qemu fork includes support for dialing between emulators (and SMSs).  I've seen this work in android builds.  In gonk, however, this doesn't work.  Here's the logcat I get

I/Gonk    (   32): Failed to create GL context for fb, trying /dev/fb0
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/Gonk    (   32):   parent isn't top window, bailing
I/Gecko   (   32): -*- TelephonyWorker component: Received message: {"type":"radiostatechange","radioState":"off"}
I/Gecko   (   32): -*- TelephonyWorker component: Received message: {"type":"cardstatechange","cardState":"ready"}
I/Gecko   (   32): -*- TelephonyWorker component: Received message: {"type":"operatorchange","operator":{"alphaLong":"Android","alphaShort":"Android","numeric":"310260"}}
I/Gecko   (   32): -*- TelephonyWorker component: Received message: {"type":"signalstrengthchange","signalStrength":{"gsmSignalStrength":7,"gsmBitErrorRate":99,"cdmaDBM":0,"cdmaECIO":0,"evdoDBM":0,"evdoECIO":0,"evdoSNR":0}}
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
W/AudioSystem(   34): AudioFlinger not published, waiting...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
E/GeckoConsole(   32): [JavaScript Warning: "WebGL: Can't get a usable WebGL context" {file: "http://localhost:8888/apps/homescreen/js/scenegraph.js" line: 114}]
E/GeckoConsole(   32): [JavaScript Warning: "WebGL: Can't get a usable WebGL context" {file: "http://localhost:8888/apps/homescreen/js/scenegraph.js" line: 114}]
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
W/AudioSystem(   34): AudioFlinger not published, waiting...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
W/AudioSystem(   34): AudioFlinger not published, waiting...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
W/AudioSystem(   34): AudioFlinger not published, waiting...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
W/AudioSystem(   34): AudioFlinger not published, waiting...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
W/AudioSystem(   34): AudioFlinger not published, waiting...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
W/AudioSystem(   34): AudioFlinger not published, waiting...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/Gecko   (   32): -*- TelephonyWorker component: Dialing 5556
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/ServiceManager(   34): Waiting for service media.audio_flinger...
W/AudioSystem(   34): AudioFlinger not published, waiting...


(Note the "TelephonyWorker component: Dialing 5556" near the end.)

After that, there's no more logging from anything ril-related, and the dialer screen just hangs.

This looks somewhat suspicious

I/Gecko   (   32): -*- TelephonyWorker component: Received message: {"type":"radiostatechange","radioState":"off"}

with no corresponding "radioState": "on".  Are we supposed to be doing that?
Here's the complete radio log for an outgoing dial

D/RILPROXY(   33): rilproxyd trigger file not found, listening on /dev/socket/rilproxy
D/RILPROXY(   33): Converted to radio account
D/RILPROXY(   33): Waiting on socket
D/RILD    (   31): overriding with -s /dev/socket/qemud
I/RIL     (   31): Opening socket /dev/socket/qemud
D/AT      (   31): AT> ATE0Q0V1
D/AT      (   31): AT< OK
D/AT      (   31): AT> ATE0Q0V1
D/AT      (   31): AT< OK
D/AT      (   31): AT> ATS0=0
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CMEE=1
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CREG=2
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CGREG=1
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CCWA=1
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CMOD=0
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CMUT=0
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CSSN=0,1
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+COLP=0
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CSCS="HEX"
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CUSD=1
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CGEREP=1,0
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CMGF=0
D/AT      (   31): AT< %CTZV: 11/12/23:22:56:02-32:0:posix!US!Pacific
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CFUN?
D/AT      (   31): AT< +CFUN: 0
D/AT      (   31): AT< OK
D/RILPROXY(   33): Socket connected
D/RILPROXY(   33): Connecting to socket rild
D/RILPROXY(   33): Connected to socket rild
I/RILC    (   31): libril: new connection
I/RILC    (   31): RIL Daemon version: android reference-ril 1.0
D/RIL     (   31): onRequest: BASEBAND_VERSION
D/RIL     (   31): onRequest: SCREEN_STATE
D/RIL     (   31): onRequest: RADIO_POWER
D/AT      (   31): AT> AT+CFUN=1
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CPIN?
D/AT      (   31): AT< +CPIN: READY
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CSMS=1
D/AT      (   31): AT< +CSMS: 1, 1, 1
D/AT      (   31): AT< OK
D/AT      (   31): AT> AT+CNMI=1,2,2,1,1
D/AT      (   31): AT< OK
D/RIL     (   31): onRequest: GET_SIM_STATUS
D/AT      (   31): AT> AT+CPIN?
D/AT      (   31): AT< +CPIN: READY
D/AT      (   31): AT< OK
D/RIL     (   31): onRequest: REGISTRATION_STATE
D/AT      (   31): AT> AT+CREG?
D/AT      (   31): AT< +CREG: 2,1, "ffffffff", "ffffffff"
D/AT      (   31): AT< OK
D/RIL     (   31): onRequest: GPRS_REGISTRATION_STATE
D/AT      (   31): AT> AT+CGREG?
D/AT      (   31): AT< +CGREG: 1,1,"ffffffff","ffffffff","0003"
D/AT      (   31): AT< OK
D/RIL     (   31): onRequest: OPERATOR
D/AT      (   31): AT> AT+COPS=3,0;+COPS?;+COPS=3,1;+COPS?;+COPS=3,2;+COPS?
D/AT      (   31): AT< +COPS: 0,0,"Android"
D/AT      (   31): AT< +COPS: 0,1,"Android"
D/AT      (   31): AT< +COPS: 0,2,"310260"
D/AT      (   31): AT< OK
D/RIL     (   31): onRequest: QUERY_NETWORK_SELECTION_MODE
D/AT      (   31): AT> AT+COPS?
D/AT      (   31): AT< +COPS: 0,2,310260
D/AT      (   31): AT< OK
D/RIL     (   31): onRequest: SIGNAL_STRENGTH
D/AT      (   31): AT> AT+CSQ
D/AT      (   31): AT< +CSQ: 7,99
D/AT      (   31): AT< OK
D/RIL     (   31): onRequest: DIAL
D/AT      (   31): AT> ATD5556;
D/AT      (   31): AT< OK
D/AT      (   31): AT< RING
D/RIL     (   31): onRequest: GET_CURRENT_CALLS
D/AT      (   31): AT> AT+CLCC
D/AT      (   31): AT< +CLCC: 1,0,3,0,0,"15555215556",129
D/AT      (   31): AT< OK


"D/AT      (   31): AT< +CLCC: 1,0,3,0,0,"15555215556",129" looks suspicious, but I don't speak AT-ese.
Calling between two qemu instances seems fine, i.e. for two emulators, dialing from 5554, to 5556, we see on first dial (note: onRequest means rild was sent a message from ril_worker)

-----

5554:

D/RIL     (   31): onRequest: DIAL
D/AT      (   31): AT> ATD5556;
D/AT      (   31): AT< OK
D/AT      (   31): AT< RING

5556:

D/AT      (   30): AT< RING
D/RIL     (   30): onRequest: GET_CURRENT_CALLS
D/AT      (   30): AT> AT+CLCC
D/AT      (   30): AT< +CLCC: 1,1,4,0,0,"15555215554",129
D/AT      (   30): AT< OK

-----

On hanging up and subsequent dials:

-----

5554:

D/RIL     (   31): onRequest: HANGUP
D/AT      (   31): AT> AT+CHLD=1-1
D/AT      (   31): AT< OK
D/RIL     (   31): onRequest: DIAL
D/AT      (   31): AT> ATD5556;
D/AT      (   31): AT< OK

5556:

D/AT      (   30): AT< RING

-----

So, it seems that we're not getting the state updates we expect from the phone in ril_worker when it's being run in the emulator.
This is m-c pre-latest-merge (not propagated to b2g yet), so maybe there's a fix that hasn't been pulled in yet.  Was waiting on a couple of build fixes to land, but the tree's closed and reviewers are on vacation, so may just merge anyway.
To test this, I bring up two emulators, then have the 5556 emulator rilproxy point to rilproxyd (adb shell into emulator, run "echo 1 > /data/local/rilproxyd", kill rilproxy process and let it restart). I forward the 5556 emulator rilproxyd port via adb, and connect to it thru b2g-js-ril to try and debug it thru a desktop firefox instance. When I dial from 5554 to 5556, b2g-js-ril sees the request and calls REQUEST_GET_CURRENT_CALLS. After it gets the call list back, it tries to parse the list, has a bunch of bytes left over, and then freezes firefox. I'm attaching a screenshot of the final log during freeze.
Ok, I can't seem to get it to repeat right now, but I had a frozen firefox window left open and for some reason it updated the frame, showing a current calls list with a phone number that had a TON of garbage after it. So it could be that the phone number string packing from reference-ril is incorrect, which is why things don't happen on the phone and freeze on desktop. Definitely something to look into.
Commented out number parsing in ril_worker.js REQUEST_GET_CURRENT_CALLS() and the freezes stop. It looks like we're expecting parcel-type strings from the phone, and from what I can tell, reference-ril sends c-strings with no length. So, we try and read a length that's actually a string, and things go crazy. However, there's no special java code for this in RIL.java, so that doesn't make any sense.
Ignore last comment. String conversion happens in libril, not reference-ril, so we're getting strings in the correct format (checked b2g-js-ril binary dumps). However, there's still some alignment we're not following that's causing this.
Ok. in ril_worker.js, removing the line 

somethingOrOther:   Buf.readUint32(), //XXX TODO whatziz? not in ril.h, but it's in the output...

(https://github.com/philikon/b2g-js-ril/blob/master/ril_worker.js#L829)

makes things stop freezing. On both the phone and the desktop, we then get stuck in a loop calling REQUEST_GET_CURRENT_CALLS over and over. It doesn't seem to be sending any DOM messages (like we would expect to bring up the incoming call dialog), meaning we're probably not getting calls states correctly from the call list or something?
(In reply to Kyle Machulis [:kmachulis] [:qdot] from comment #8)
> Ok. in ril_worker.js, removing the line 
> 
> somethingOrOther:   Buf.readUint32(), //XXX TODO whatziz? not in ril.h, but
> it's in the output...
> 
> (https://github.com/philikon/b2g-js-ril/blob/master/ril_worker.js#L829)
> 
> makes things stop freezing.

Filed bug 716709 for this. This bug remains for the rest of the emulator breakage (loops, etc.)
With b2g tip, when I load the dialer app, it only loads partially and then the UI goes completely unresponsive.  I can't exit out of the dialer or pull down the status bar area.  This seems like a pretty bad, possibly separate bug.  If removing the attempt to parse the extra int makes the freeze go away, then we still have a bug in that the freeze happened in the first place.

Nothing suspicious in logcat.  emulator process is using 100% CPU but that's not unusual :/.  Battery-status indicator not updating either.
Commenting out parsing the extra int doesn't help.  The dialer seems to freeze around the time the "contacts" icon on the bottom of the screen loads, so this might be related to IDB stuff and not telephony?

(gdb is barfing for me in the emulator, on to console.log tomorrow.)
(In reply to Chris Jones [:cjones] [:warhammer] from comment #10)
> Battery-status indicator not updating either.

The battery problem seems to have been introduced when switching to the gonk backend in the emulator; see https://github.com/andreasgal/B2G/issues/121.
Sorry, I meant that the CSS animation stops animating.  That works fine until we hit the stall in the dialer app.
//    TonePlayer.init();

makes the hang go away.  Sigh.
(In reply to Chris Jones [:cjones] [:warhammer] from comment #14)
> //    TonePlayer.init();
> 
> makes the hang go away.  Sigh.

:(

Thanks for digging through this, Chris. Fabrice had a good idea for finding out what device we're on, by using getprop. I can just do the equivalent of 

  char propValue[32];
  property_get("ril.model_id", propValue, NULL);

in js-ctypes in the ril_worker.js to find out whether we need the 'somethingOrOther' uint32 in the call state.

I'll do that and see what other problems we're going to hit.
Assignee: nobody → philipp
I only got back to the point of the endless REQUEST_GET_CURRENT_CALLS, but haven't had a chance to dig further.  So that's still happening.

Thanks for grabbing this!
What I see happening is that we set up the call properly (AFAICT), find it in GET_CURRENT_CALLS, but then we get an error on a request

I/Gecko   (   32): RIL Worker: Received error 6 for solicited parcel type 53

Looking into that.  From there on, the state of the call never changes, but RIL keeps notifying us of CALL_STATE_CHANGED for some reason.  It stays in state ALERTING forever.  First part of the log below, the rest repeats.

I/Gecko   (   32): -*- RadioInterfaceLayer: Dialing 5556
I/Gecko   (   32): RIL Worker: Outgoing parcel: 0,0,0,36,10,0,0,0,11,0,0,0,4,0,0,0,53,0,53,0,53,0,54,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
I/Gecko   (   32): RIL Worker: Solicited response for request type 10, token 11
I/Gecko   (   32): RIL Worker: Handling parcel as REQUEST_DIAL
W/AudioSystem(   34): AudioFlinger not published, waiting...
I/Gecko   (   32): RIL Worker: Unsolicited response for request type 1001
I/Gecko   (   32): RIL Worker: Handling parcel as UNSOLICITED_RESPONSE_CALL_STATE_CHANGED
I/Gecko   (   32): RIL Worker: Outgoing parcel: 0,0,0,8,9,0,0,0,12,0,0,0
I/Gecko   (   32): RIL Worker: Solicited response for request type 9, token 12
I/Gecko   (   32): RIL Worker: Handling parcel as REQUEST_GET_CURRENT_CALLS
I/Gecko   (   32): RIL Worker:   RESPONSE LENGTH: 80, calls_length: 1
I/Gecko   (   32): RIL Worker:   got call
I/ServiceManager(   34): Waiting for service media.audio_flinger...
I/Gecko   (   32): RIL Worker:     call.state = 3
I/Gecko   (   32): RIL Worker:     call.callIndex = 1
I/Gecko   (   32): RIL Worker:     call.toa = 129
I/Gecko   (   32): RIL Worker:     call.isMpty = false
I/Gecko   (   32): RIL Worker:     call.isMT = false
I/Gecko   (   32): RIL Worker:     call.als = 0
I/Gecko   (   32): RIL Worker:     call.isVoice = true
I/Gecko   (   32): RIL Worker:     call.isVoicePrivacy = false
I/Gecko   (   32): RIL Worker:     call.number = 15555215556
I/Gecko   (   32): RIL Worker:     call.numberPresentation = 0
I/Gecko   (   32): RIL Worker:     call.name = null
I/Gecko   (   32): RIL Worker:     call.namePresentation = 0
I/Gecko   (   32): RIL Worker:     call.uusInfo = null
I/Gecko   (   32): RIL Worker: GOT NEW CALL 1
I/Gecko   (   32): RIL Worker: SENDING CALL STATE CHANGED FOR 1 to 3
I/Gecko   (   32): RIL Worker: Outgoing parcel: 0,0,0,16,53,0,0,0,13,0,0,0,1,0,0,0,0,0,0,0
I/Gecko   (   32): RIL Worker: Received error 6 for solicited parcel type 53
I/Gecko   (   32): -*- RadioInterfaceLayer: Received message: {"type":"callStateChange","call":{"callIndex":1,"state":3,"number":"15555215556","name":null}}
I/Gecko   (   32): -*- RadioInterfaceLayer: handleCallStateChange: {"callIndex":1,"state":3,"number":"15555215556","name":null}
I/ServiceManager(   32): Waiting for service media.audio_policy...
I/Gecko   (   32): RIL Worker: Unsolicited response for request type 1001
I/Gecko   (   32): RIL Worker: Handling parcel as UNSOLICITED_RESPONSE_CALL_STATE_CHANGED
The failing request is SET_MUTE, so this looks benign.  Bug appears to be on the receiving side.
Like comment 8 says, we're receiving the call properly in RIL land, and appear to be sending the right message to DOM land

I/Gecko   (   31): RIL Worker: Unsolicited response for request type 1001
I/Gecko   (   31): RIL Worker: Handling parcel as UNSOLICITED_RESPONSE_CALL_STATE_CHANGED
I/Gecko   (   31): RIL Worker: Outgoing parcel: 0,0,0,8,9,0,0,0,11,0,0,0
I/Gecko   (   31): RIL Worker: Solicited response for request type 9, token 11
I/Gecko   (   31): RIL Worker: Handling parcel as REQUEST_GET_CURRENT_CALLS
I/Gecko   (   31): RIL Worker:   RESPONSE LENGTH: 80, calls_length: 1
I/Gecko   (   31): RIL Worker:   got call
I/Gecko   (   31): RIL Worker:     call.state = 4
I/Gecko   (   31): RIL Worker:     call.callIndex = 1
I/Gecko   (   31): RIL Worker:     call.toa = 129
I/Gecko   (   31): RIL Worker:     call.isMpty = false
I/Gecko   (   31): RIL Worker:     call.isMT = true
I/Gecko   (   31): RIL Worker:     call.als = 0
I/Gecko   (   31): RIL Worker:     call.isVoice = true
I/Gecko   (   31): RIL Worker:     call.isVoicePrivacy = false
I/Gecko   (   31): RIL Worker:     call.number = 15555215554
I/Gecko   (   31): RIL Worker:     call.numberPresentation = 0
I/Gecko   (   31): RIL Worker:     call.name = null
I/Gecko   (   31): RIL Worker:     call.namePresentation = 0
I/Gecko   (   31): RIL Worker:     call.uusInfo = null
I/Gecko   (   31): RIL Worker: GOT NEW CALL 1
I/Gecko   (   31): RIL Worker: SENDING CALL STATE CHANGED FOR 1 to 4

(the last logline is just above |this.sendDOMMessage(message);|, in _handleCallChangedState().
The final symptom here is that we're not getting a DOM notification in the dialer, unsurprisingly.  We never hit

  handleEvent: function fm_handleEvent(evt) {
//...
      case 'incoming':
        dump('DIALER: incoming call from ' + evt.call.number);

Will start bisecting the path between RIL <--> content JS.
The problem is that both the caller and callee are hanging on the main thread when they try to change audio state.  That the RIL threads keep going is very misleading.
This turns out to have nothing to do with telephony, except for the fact that it happens to step on the landmine first.

The gonk guts have two modes: one used normally, on real HW, where most (but not all) system services get spawned as separate processes.  The other is used in the emulator, and all the system services get spawned in the system_server process.  (Why, I dunno.)  So here in the emulator, we never initialize the audio service, and the audio IPC client blocks forever waiting for the service to come up.  The first code to touch audio burns its finger.

This sort of argues again for us not using the media player service, which will make andreas happy.

For now, I think the right fix here is to do the same initialization hack in gecko.  It's getting pretty involved so I'll go ahead and steal this.  I've got what looks like a right fix, but getting a crash initializing the audio service.  Investigating.
Assignee: philipp → nobody
Component: DOM: Device Interfaces → Video/Audio
QA Contact: device-interfaces → video.audio
Summary: Phone calls not working in emulator → Audio (and other services) not initialized in emulator
Er, I think the assignee got reset when I switched component.
Assignee: nobody → jones.chris.g
The analysis of comment 22 was wrong: I made an assumption based on some comments that turned out to be wrong, and likely very ancient.  The mediaserver process *was* running in the emulator.  The problem was that initializing the AudioPolicyService was hanging trying to get the AudioFlingerService.  This was a bit puzzling because audioflinger is initialized just before the AudioPolicyService, but it turns out we weren't starting the servicemanager process in the emulator.  Whups!  So basically a one-line fix.

Already merged to b2g https://github.com/cgjones/android-system-core/commit/c6e8ef66e939ed97ff290910bc5e52d1086e9c46

With the hacky fix for bug 716709 applied, I successfully made a phone call between two emulator instances.
Status: NEW → RESOLVED
Closed: 12 years ago
Resolution: --- → FIXED
No longer depends on: 716709
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: