On May 22, 2012, at 2:03 PM, Grant Erickson wrote:
> Picking up a thread from IRC, I've been working on getting agent-based
> service connections working with connman-1.0. However, what I've found is
> that rather than performing the following sequence of operations:
>
> 1) Issue .Service.Connect call.
> 2) Receive properties dictionary from .Agent.RequestInput call.
> 3) Post message to UI with a closure context for the async pending
> .Agent.RequestInput call.
> 4) Gather requested input.
> 5) Create a response dictionary
> 6) Complete closure context and send D-Bus reply back to initial
> .Agent.RequestInput call.
>
> What I see happening instead is:
>
> 1) Issue .Service.Connect call.
> 2) Receive .Service.PropertiesChanged call with State = failure.
> 3) Receive net.connman.Error.Failed: Input/output error error in
> response to (1).
> 4) Receive properties dictionary from .Agent.RequestInput call.
>
> and things generally fall apart from there. Debugging this, in particular the
> source of the -EIO asynchronous cancellation in the middle of the connect
> request, what I find is the following:
>
> 23.000 debug connmand: --> (3) connect_service:
> service 0xaa320
> 23.000 debug connmand: --> (4)
> __connman_service_connect: service 0xaa320 state idle
> 23.000 info connmand: User-requested connection to service "Test"
> identifier "wifi_02283e3d4347_65547473_managed_psk".
> 23.000 debug connmand: service_connect returned -126 (Required key not
> available)
> 23.000 debug connmand: __connman_error_failed: msg 0xa0698 errnum 5
> (Input/output error)
> 23.000 err connmand: ++++++++ backtrace ++++++++
> 24.000 err connmand: #0 0x31078 in reply_pending() at
> src/service.c:3315
> 24.000 err connmand: #1 0x35010 in service_complete() at
> src/service.c:4383
> 24.000 err connmand: #2 0x35288 in service_indicate_state() at
> src/service.c:4749
> 24.000 err connmand: #3 0x35628 in
> __connman_service_ipconfig_indicate_state() at src/service.c:5041
> 24.000 err connmand: #4 0x35f04 in __connman_service_connect() at
> src/service.c:5291
> 24.000 err connmand: #5 0x36520 in connect_service() at
> src/service.c:3449
> 24.000 err connmand: #6 0x13130 in process_message() at
> gdbus/object.c:199
> 24.000 err connmand: #7 0x40163e84 in /lib/libdbus-1.so.3
> 24.000 err connmand: #8 0x4014f5d4 in /lib/libdbus-1.so.3
> 24.000 err connmand: #9 0x12090 in message_dispatch() at
> gdbus/mainloop.c:76
> 24.000 err connmand: #10 0x4006773c in /lib/libglib-2.0.so.0
> 24.000 err connmand: #11 0x40066db4 in /lib/libglib-2.0.so.0
> 24.000 err connmand: #12 0x4006ab98 in /lib/libglib-2.0.so.0
> 24.000 err connmand: #13 0x4006b148 in /lib/libglib-2.0.so.0
> 24.000 err connmand: #14 0x27788 in main() at src/main.c:562
> 24.000 err connmand: +++++++++++++++++++++++++++
> 24.000 debug connmand: service->network 0xa8e48
> 24.000 debug connmand: --> (5)
> __connman_network_disconnect: network 0xa8e48
> 24.000 debug connmand: user connect 1, error is -126 (Required key not
> available)
> 24.000 debug connmand: --> (6)
> __connman_agent_request_passphrase_input: service 0xaa320 callback 0x369d4
> user_data (nil)
> 24.000 debug connmand: <-- (6)
> __connman_agent_request_passphrase_input: err -5 (Input/output error)
> 24.000 debug connmand: <-- (5)
> __connman_service_connect: err -115 (Operation now in progress)
> 24.000 debug connmand: __connman_service_connect returned -115
> (Operation now in progress)
> 24.000 debug connmand: return 2
> 24.000 debug connmand: <-- (4)
> connect_service: reply (nil)
>
> So, it would appear that service_indicate_state is killing the
> .Service.Connect call prematurely for reasons yet to be determined.
I've done a bit more debugging on this and one factor seems to be setting both
the IPv4 and IPv6 state in __connman_service_connect to _STATE_FAILURE. As an
experiment, I changed the values there to _STATE_IDLE and things started to
behave more as expected with the order of operations occurring as in 1-6 above;
however, the default .Agent.RequestInput timeout (20s) was entirely too short
as the call timed out before I was finished entering the passphrase.
Why do we set the IPv4 and IPv6 state to FAILURE rather than IDLE?
12.000 debug connmand[1107]: --> (1) connect_service: service 0xa63f8
12.000 debug connmand[1107]: --> (2) __connman_service_connect:
service 0xa63f8 state idle
12.000 info connmand[1107]: User-requested connection to
service "Test" identifier "wifi_02283e3d4347_65547473_managed_psk".
12.000 debug connmand[1107]: service_connect: service 0xa63f8
12.000 debug connmand[1107]: service_connect returned -126
(Required key not available)
12.000 debug connmand[1107]: --> (3)
__connman_service_ipconfig_indicate_state: service 0xa63f8 new_state 7 type 1
12.000 debug connmand[1107]: service 0xa63f8
(wifi_02283e3d4347_65547473_managed_psk) state 7 (failure) type 1 (IPv4)
12.000 debug connmand[1107]: --> (4)
service_indicate_state: service 0xa63f8
12.000 debug connmand[1107]: service 0xa63f8 old idle -
new failure/idle => failure
12.000 debug connmand[1107]: --> (5) service_complete:
service 0xa63f8
12.000 debug connmand[1107]: --> (6) reply_pending:
service 0xa63f8 pending 0x9a428 error 5 (Input/output error)
12.000 debug connmand[1107]:
__connman_error_failed: msg 0x9a428 errnum 5 (Input/output error)
### Existing .Service.Connect call is prematurely terminated here ---^
12.000 err connmand[1107]: ++++++++
backtrace ++++++++
13.000 err connmand[1107]: #0 0x310cc in
reply_pending() at src/service.c:3317
13.000 err connmand[1107]: #1 0x350d4 in
service_complete() at src/service.c:4389
13.000 err connmand[1107]: #2 0x35398 in
service_indicate_state() at src/service.c:4759
13.000 err connmand[1107]: #3 0x35828 in
__connman_service_ipconfig_indicate_state() at src/service.c:5068
13.000 err connmand[1107]: #4 0x36218 in
__connman_service_connect() at src/service.c:5324
13.000 err connmand[1107]: #5 0x36840 in
connect_service() at src/service.c:3453
13.000 err connmand[1107]: #6 0x13130 in
process_message() at gdbus/object.c:199
13.000 err connmand[1107]: #7 0x40163e84 in
/lib/libdbus-1.so.3
13.000 err connmand[1107]: #8 0x4014f5d4 in
/lib/libdbus-1.so.3
13.000 err connmand[1107]: #9 0x12090 in
message_dispatch() at gdbus/mainloop.c:76
13.000 err connmand[1107]: #10 0x4006773c in
/lib/libglib-2.0.so.0
13.000 err connmand[1107]: #11 0x40066db4 in
/lib/libglib-2.0.so.0
13.000 err connmand[1107]: #12 0x4006ab98 in
/lib/libglib-2.0.so.0
13.000 err connmand[1107]: #13 0x4006b148 in
/lib/libglib-2.0.so.0
13.000 err connmand[1107]: #14 0x27788 in
main() at src/main.c:562
13.000 err connmand[1107]:
+++++++++++++++++++++++++++
13.000 debug connmand[1107]: <-- (6) reply_pending:
13.000 debug connmand[1107]: <-- (5) service_complete:
13.000 debug connmand[1107]: <-- (4)
service_indicate_state: end 0
13.000 debug connmand[1107]: service_indicate_state
returned 0 (Success)
13.000 debug connmand[1107]: <-- (3)
__connman_service_ipconfig_indicate_state: ret 0 (Success)
13.000 debug connmand[1107]: --> (3)
__connman_service_ipconfig_indicate_state: service 0xa63f8 new_state 7 type 2
13.000 debug connmand[1107]: service 0xa63f8
(wifi_02283e3d4347_65547473_managed_psk) state 7 (failure) type 2 (IPv6)
13.000 debug connmand[1107]: --> (4)
service_indicate_state: service 0xa63f8
13.000 debug connmand[1107]: service 0xa63f8 old
failure - new failure/failure => failure
13.000 debug connmand[1107]: <-- (4)
service_indicate_state: -114 (Operation already in progress)
13.000 debug connmand[1107]: service_indicate_state
returned -114 (Operation already in progress)
13.000 debug connmand[1107]: <-- (3)
__connman_service_ipconfig_indicate_state: ret -114 (Operation already in
progress)
13.000 debug connmand[1107]: service->network 0xa6190
13.000 debug connmand[1107]: --> (3)
__connman_network_disconnect: network 0xa6190
13.000 debug connmand[1107]: <-- (3)
__connman_network_disconnect:
13.000 debug connmand[1107]: user connect 1, error is -126 (Required
key not available)
13.000 debug connmand[1107]: --> (3)
__connman_agent_request_passphrase_input: service 0xa63f8 callback 0x36cf4
user_data (nil)
13.000 debug connmand[1107]: <-- (3)
__connman_agent_request_passphrase_input: err -5 (Input/output error)
13.000 debug connmand[1107]: <-- (2) __connman_service_connect: err
-115 (Operation now in progress)
13.000 debug connmand[1107]: __connman_service_connect returned -115
(Operation now in progress)
13.000 debug connmand[1107]: service->pending (nil), returning with no
reply
13.000 debug connmand[1107]: <-- (1) connect_service: reply (nil)
Best,
Grant
_______________________________________________
connman mailing list
[email protected]
http://lists.connman.net/listinfo/connman
