3:17 a.m.
Hi,
I'm doing some post mortem of a connman process which started to behave
strangely and didn't manage to connect to the Wifi network it should have
connected to for a week (before I forced a core dump and restarted it, which
made everything work again). The error returned to the other process over
DBus after calling service.Connect() was -EIO, which after some investigation
into the source code seems to indicate that the error originates from
service_complete().
Digging into the core dump I found some things that could explain the error:
(gdb) print ((struct connman_service
*)(service_list->next->next->data))->name
$157 = 0x1714f38 "B<snip>-2G"
(gdb) print ((struct connman_service
*)(service_list->next->next->data))->network
$158 = (struct connman_network *) 0x1722588
(gdb) print ((struct connman_service
*)(service_list->next->next->data))->network->device
$159 = (struct connman_device *) 0x0
(gdb) print ((struct connman_service
*)(service_list->next->next->data))->network->driver
$160 = (struct connman_network_driver *) 0x0
(gdb) print ((struct connman_service
*)(service_list->next->next->data))->network->name
$161 = 0x17224b8 "B<snip>-2G"
network->{driver,device} being NULL explains why -EIO is returned. I'm thinking
that should not happen. I also found another connman_network when digging
into what the supplicant interface was seeing, and that's not the same network
that the service holds a reference to..
(gdb) print ((struct connman_network *)((struct wifi_data *)((GSupplicantInterface
*)interface_table->values[1])->data)->networks[0]->next->next->next->next->next->next->next->next->next->next->next->data)->name
$168 = 0x173cc30 "B<snip>-2G"
(gdb) print ((struct connman_network *)((struct wifi_data *)((GSupplicantInterface
*)interface_table->values[1])->data)->networks[0]->next->next->next->next->next->next->next->next->next->next->next->data)
$169 = (struct connman_network *) 0x172d310
So, I don't have any logs that tells me anything useful since debugging was not
enabled, but I do have the core dump. It sort of feels like a missing deref on that
service somewhere.
Monitoring dbus during a connection attempt:
‣ Type=method_call Endian=l Flags=0 Version=1 Priority=0 Cookie=239369
Sender=:1.12 Destination=net.connman
Path=/net/connman/service/wifi_24[..snip..]3247_managed_psk Interface=net.connman.Service
Member=Connect
UniqueName=:1.12
MESSAGE "" {
};
‣ Type=signal Endian=l Flags=1 Version=1 Priority=0 Cookie=530610
Sender=:1.10 Path=/net/connman/service/wifi_24[..snip..]3247_managed_psk
Interface=net.connman.Service Member=PropertyChanged
UniqueName=:1.10
MESSAGE "sv" {
STRING "State";
VARIANT "s" {
STRING "idle";
};
};
‣ Type=method_call Endian=l Flags=0 Version=1 Priority=0 Cookie=530611
Sender=:1.10 Destination=:1.12 Path=/ Interface=net.connman.Agent
Member=RequestInput
UniqueName=:1.10
MESSAGE "oa{sv}" {
OBJECT_PATH
"/net/connman/service/wifi_24[..snip..]3247_managed_psk";
ARRAY "{sv}" {
DICT_ENTRY "sv" {
STRING "Passphrase";
VARIANT "a{sv}" {
ARRAY "{sv}" {
DICT_ENTRY "sv" {
STRING "Type";
VARIANT "s" {
STRING "psk";
};
};
DICT_ENTRY "sv" {
STRING "Requirement";
VARIANT "s" {
STRING "mandatory";
};
};
DICT_ENTRY "sv" {
STRING "Alternates";
VARIANT "as" {
ARRAY "s" {
STRING
"WPS";
};
};
};
};
};
};
DICT_ENTRY "sv" {
STRING "WPS";
VARIANT "a{sv}" {
ARRAY "{sv}" {
DICT_ENTRY "sv" {
STRING "Type";
VARIANT "s" {
STRING "wpspin";
};
};
DICT_ENTRY "sv" {
STRING "Requirement";
VARIANT "s" {
STRING "alternate";
};
};
};
};
};
};
};
‣ Type=method_return Endian=l Flags=1 Version=1 Priority=0 Cookie=239370
ReplyCookie=530611
Sender=:1.12 Destination=:1.10
UniqueName=:1.12
MESSAGE "a{sv}" {
ARRAY "{sv}" {
DICT_ENTRY "sv" {
STRING "Passphrase";
VARIANT "s" {
STRING <redacted>;
};
};
};
};
‣ Type=signal Endian=l Flags=1 Version=1 Priority=0 Cookie=530612
Sender=:1.10 Path=/net/connman/service/wifi_24[..snip..]3247_managed_psk
Interface=net.connman.Service Member=PropertyChanged
UniqueName=:1.10
MESSAGE "sv" {
STRING "State";
VARIANT "s" {
STRING "failure";
};
};
‣ Type=error Endian=l Flags=1 Version=1 Priority=0 Cookie=530613 ReplyCookie=239369
Sender=:1.10 Destination=:1.12
ErrorName=net.connman.Error.Failed ErrorMessage="Input/output error"
UniqueName=:1.10
MESSAGE "s" {
STRING "Input/output error";
};
‣ Type=method_call Endian=l Flags=0 Version=1 Priority=0 Cookie=239371
Sender=:1.12 Destination=net.connman
Path=/net/connman/service/wifi_24[..snip..]3247_managed_psk Interface=net.connman.Service
Member=Remove
UniqueName=:1.12
MESSAGE "" {
};
‣ Type=method_return Endian=l Flags=1 Version=1 Priority=0 Cookie=530614
ReplyCookie=239371
Sender=:1.10 Destination=:1.12
UniqueName=:1.10
MESSAGE "" {
};
And that's about all I got so far, but it was stuck in this state for at least
a week and a new wifi scan was triggered periodically during that time.
Any pointers, suggestions, comments, etc that could either tell me that
I'm doing something wrong interacting with connman, or where to look
further?
I'm on connman 1.35 btw because of reasons, but I didn't find anything
in the connman history since that point that should have fixed this. But
I'm gladly proven wrong.
Thanks,
--
Henrik
8:35 a.m.
New subject: IFA_F_PERMANENT always set
I noticed that unlike other network managers, connman always sets ifa_flags
= IFA_F_PERMANENT, regardless if DHCP is in use.
Because of this, ip addr, for example, never reports "dynamic" for the IPv4
address when DHCP is in use.
Is there a reason for this?
Thanks!
11:56 a.m.
New subject: IFA_F_PERMANENT always set
Hi Nuno,
On Fri, Mar 08, 2019 at 05:35:24PM +0100, Nuno Gonçalves wrote:
I noticed that unlike other network managers, connman always sets
ifa_flags
= IFA_F_PERMANENT, regardless if DHCP is in use.
Because of this, ip addr, for example, never reports "dynamic" for the IPv4
address when DHCP is in use.
Is there a reason for this?
No, I don't think so. It is likely just a 'missing' feature. It looks
no one cared to fix up the code path from the DHCP source to the code
snippet where we set the flag.
Thanks,
Daniel
11:53 a.m.
Hi Henrik,
On Thu, Feb 28, 2019 at 11:17:12AM +0000, Henrik Persson wrote:
network->{driver,device} being NULL explains why -EIO is returned.
I'm thinking
that should not happen. I also found another connman_network when digging
into what the supplicant interface was seeing, and that's not the same network
that the service holds a reference to..
network->driver is set to NULL in network_remove(). I don't thin
network_probe() is involved in your scenario. That would indicate that
wpa_s decided to remove the network.
Any pointers, suggestions, comments, etc that could either tell me
that
I'm doing something wrong interacting with connman, or where to look
further?
I think trying to get hold on the logs would be a good starting point,
so the connman log and the wpa_supplicant log. Furthermore, set the
CONNMAN_SUPPLICANT_DEBUG environment variable. That should give you
what ConnMan thinks wpa_supplicant is doing.
BTW, which version of wpa_s are you using?
I'm on connman 1.35 btw because of reasons, but I didn't find
anything
in the connman history since that point that should have fixed this. But
I'm gladly proven wrong.
I suggest to give the current HEAD a try, we never know :)
Thanks,
Daniel
5:14 a.m.
Hi Daniel,
On 2019-03-10 19:53, Daniel Wagner wrote:
> network->{driver,device} being NULL explains why -EIO is
returned. I'm thinking
> that should not happen. I also found another connman_network when digging
> into what the supplicant interface was seeing, and that's not the same network
> that the service holds a reference to..
network->driver is set to NULL in network_remove(). I don't thin
network_probe() is involved in your scenario. That would indicate that
wpa_s decided to remove the network.
Yeah, and then added again at some later point. But the service was
never updated. I'm trying to debug another strange behavior that I
haven't reported yet, where I get in a state when trying to connect to a
AP with a hidden SSID and I always get -EIO on that connection attempt,
unless I wait for a few (milli)seconds before calling Connect over DBus
after the Services changed dbus notification arrives. I think that it
might be a race between the service getting updated once, triggering my
connect()-attempt and then being updated again which is blocked in
update_from_network() since we're connecting. Adding a timer and just
waiting a bit makes everything work again, so.. I guess the same thing
might happen here.
It feels strange that a service with network->driver set to null is
still returned in the list, and obviously still has a refcount..
> Any pointers, suggestions, comments, etc that could either tell
me that
> I'm doing something wrong interacting with connman, or where to look
> further?
I think trying to get hold on the logs would be a good starting point,
so the connman log and the wpa_supplicant log. Furthermore, set the
CONNMAN_SUPPLICANT_DEBUG environment variable. That should give you
what ConnMan thinks wpa_supplicant is doing.
Sure. I'm enabling debug and will try to enable the supplicant debug as
well. Good tip.
BTW, which version of wpa_s are you using?
# wpa_supplicant -v
wpa_supplicant v2.6
Which is the one in yocto which seems to be pretty much 2.6 with some
patches for the KRACK attack. I could try getting 2.7 in there..
> I'm on connman 1.35 btw because of reasons, but I didn't
find anything
> in the connman history since that point that should have fixed this. But
> I'm gladly proven wrong.
I suggest to give the current HEAD a try, we never know :)
I've now moved up to 1.36 at least. Should I feel brave enough to push
HEAD to a few thousand of our customers? :)
--
Henrik Persson
Verisure Innovation AB
596
days inactive
607
days old
4 comments
3 participants
participants (3)
-
Daniel Wagner -
Henrik Persson -
Nuno Gonçalves