I just realized that the attachment in the previous email was too big. So I
am copying certain portion of log.
Here is the instance when connman hangs with last print as "015-09-17
05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/inet.c:icmpv6_nd_recv() code 198 len 62 hdr 24"
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dhcpv6.c:do_dad() index 3
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/service.c:connman_service_lookup_from_network()
service_name wifi_18b4301c937f_2042472d57692d46692d522d54
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/service.c:connman_service_lookup_from_network()
service 0x1dc7268
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/ipconfig.c:__connman_ipconfig_ref_debug() 0x1d1d668
ref 3 by /home/bamboo/bamboo-agent-home/xml-data/buil
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dhcpv6.c:ref_own_address() 0x1d27330 ref 1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dhcpv6.c:do_dad() user 0x1d27330 address
fd4f:7aba:e4b2::305 client 0x1dc31f0 ipconfig 0x1d1d668 prefixes
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/inet.c:__connman_inet_ipv6_do_dad() sock 20
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/inet.c:ndisc_send_unspec()
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dhcpv6.c:do_dad() Sent neighbor solicitation 64 bytes
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/rtnl.c:rtnl_message() buf 0xbeaf1a78 len 108
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/rtnl.c:rtnl_message() NEWROUTE len 108 type 24 flags
0x0000 seq 0 pid 0
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/rtnl.c:rtnl_message() buf 0xbeaf1a78 len 64
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/rtnl.c:rtnl_message() NEWADDR len 64 type 20 flags
0x0000 seq 0 pid 0
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/ipconfig.c:__connman_ipconfig_newaddr() index 3
2015-09-17 05:46:57.000000 daemon.info connmand[374]: wlan0 {add} address
fdb0:74fe:4d46:0:1ab4:30ff:fe1c:937f/64 label (null) family 10
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/service.c:service_ip_bound() wlan0 ip bound
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/service.c:service_ip_bound() service 0x1dc7268
ipconfig 0x1d1d668 type 2 method 5
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/service.c:__connman_service_ipconfig_indicate_state()
service 0x1dc7268 (wifi_18b4301c937f_2042472d57692d
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/wispr.c:__connman_wispr_start() service 0x1dc7268
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/wispr.c:free_connman_wispr_portal_context() context
0x1d90860
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/wispr.c:connman_wispr_message_init()
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/wispr.c:wispr_portal_detect() wispr/portal context
0x1db0f30
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/wispr.c:wispr_portal_detect() service 0x1dc7268
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/wispr.c:wispr_portal_detect() interface wlan0
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/resolver.c:connman_resolver_append() index 3 domain
(null) server fd4f:7aba:e4b2::1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/resolver.c:append_resolver() index 3 domain (null)
server fd4f:7aba:e4b2::1 lifetime 0 flags 0
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:__connman_dnsproxy_append() index 3 server
fd4f:7aba:e4b2::1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:find_server() index 3 server
fd4f:7aba:e4b2::1 proto 17
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:append_domain() index 3 domain (null)
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/ntp.c:__connman_ntp_stop()
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/storage.c:storage_load() Loading
/var/lib/connman/settings
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/ntp.c:__connman_ntp_stop()
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/timeserver.c:__connman_timeserver_sync_next() Using
timeserver 192.168.1.1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/ntp.c:__connman_ntp_start() 192.168.1.1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/ntp.c:start_ntp() server 192.168.1.1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/service.c:service_indicate_state() service 0x1dc7268
old online - new online/ready => online
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/ipconfig.c:__connman_ipconfig_append_ipv6()
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/session.c:ipconfig_changed() service 0x1dc7268
ipconfig 0x1d1d668
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/resolver.c:__connman_resolver_redo_servers() index 3
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:__connman_dnsproxy_remove() index 3 server
fd4f:7aba:e4b2::1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:find_server() index 3 server
fd4f:7aba:e4b2::1 proto 17
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:destroy_server() index 3 server
fd4f:7aba:e4b2::1 sock 27
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:server_destroy_socket() index 3 server
fd4f:7aba:e4b2::1 proto 17
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:destroy_server() Removing DNS server
fd4f:7aba:e4b2::1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:find_server() index 3 server
fd4f:7aba:e4b2::1 proto 6
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:__connman_dnsproxy_append() index 3 server
fd4f:7aba:e4b2::1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:find_server() index 3 server
fd4f:7aba:e4b2::1 proto 17
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:create_server() index 3 server
fd4f:7aba:e4b2::1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:server_create_socket() index 3 server
fd4f:7aba:e4b2::1 proto 17
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:server_create_socket() sk 27
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:create_server() Adding DNS server
fd4f:7aba:e4b2::1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:__connman_dnsproxy_remove() index 3 server
fdb0:74fe:4d46::1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:find_server() index 3 server
fdb0:74fe:4d46::1 proto 17
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:destroy_server() index 3 server
fdb0:74fe:4d46::1 sock 16
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:server_destroy_socket() index 3 server
fdb0:74fe:4d46::1 proto 17
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:destroy_server() Removing DNS server
fdb0:74fe:4d46::1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:find_server() index 3 server
fdb0:74fe:4d46::1 proto 6
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:__connman_dnsproxy_append() index 3 server
fdb0:74fe:4d46::1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:find_server() index 3 server
fdb0:74fe:4d46::1 proto 17
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:create_server() index 3 server
fdb0:74fe:4d46::1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:server_create_socket() index 3 server
fdb0:74fe:4d46::1 proto 17
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:server_create_socket() sk 16
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/dnsproxy.c:create_server() Adding DNS server
fdb0:74fe:4d46::1
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/rtnl.c:rtnl_message() buf 0xbeaf1a78 len 108
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/rtnl.c:rtnl_message() NEWROUTE len 108 type 24 flags
0x0000 seq 0 pid 0
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/wispr.c:proxy_callback() proxy DIRECT
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/wispr.c:connman_wispr_message_init()
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/wispr.c:wispr_portal_request_portal()
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/inet.c:icmpv6_nd_event()
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/inet.c:icmpv6_nd_recv()
2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
connman/./connman/src/inet.c:icmpv6_nd_recv() code 198 len 62 hdr 24 ==>* After
this point connman is unresponsive and is restarted almost 30 minutes
later.*
2015-09-17 06:21:56.000000 daemon.info monit[483]: 'connmand' stop on
user request
2015-09-17 06:21:56.000000 daemon.info monit[483]: 'connmand' stop:
/etc/init.d/connman
2015-09-17 06:22:04.000000 daemon.info monit[483]: 'connmand' stop action
done
2015-09-17 06:25:11.000000 daemon.info monit[483]: 'connmand' start on
user request
2015-09-17 06:25:12.000000 daemon.info monit[483]: 'connmand' start:
/etc/init.d/connman
2015-09-17 06:25:12.000000 daemon.info connmand[4417]: Connection Manager
version 1.29
On Thu, Sep 17, 2015 at 7:03 PM, Naveen Singh <nav...@nestlabs.com> wrote:
> We have been seeing a very weird connmand lockup where connman gets
> unresponsive and is not able to process any events from its main loop. I
> have enabled complete logging in the connman and was able to reproduce the
> problem. In both the instances last message we see is some sort of wrong
> packet received and just before receiving the packet a wispr_portal_request.
>
>
> 1.* Device 1*: This is with log "Invalid packet timestamp from time
> server" and just before that wispr_portal_request.
>
> Look for the logs in file device1_1.log around *2015-09-17 05:39:17*
>
> *2015-09-17 05:39:17.000000 daemon.debug connmand[6704]:
> connman/./connman/src/wispr.c:wispr_portal_detect() interface wlan0*
> *2015-09-17 05:39:17.000000 daemon.debug connmand[6704]:
> connman/./connman/src/wispr.c:proxy_callback() proxy DIRECT*
> *2015-09-17 05:39:17.000000 daemon.debug connmand[6704]:
> connman/./connman/src/wispr.c:connman_wispr_message_init() *
> *2015-09-17 05:39:17.000000 daemon.debug connmand[6704]:
> connman/./connman/src/wispr.c:wispr_portal_request_portal() *
> *2015-09-17 05:39:17.000000 daemon.err connmand[6704]: Invalid packet
> timestamp from time server*
> *2015-09-17 06:19:11.000000 daemon.info <http://daemon.info> monit[417]:
> 'connmand' stop on user request*
>
> 2. *Device 2*: In this case looks like Neighbor advertisement packet is
> received but the code is not 0.(as a part of doing dad) but code is not
> zero. code not being zero is an indication that it is not a neighbor
> advertisement. Also length is different than what it should be (62 vs 32
> when it is a right neighbor advertisement). Just before this happened same
> signature for wispr_portal_request.
>
> Look for the logs in file device2_2.log around *2015-09-17
> 05:46:57.000000*
>
> 2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
> connman/./connman/src/wispr.c:wispr_portal_request_portal()
> 2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
> connman/./connman/src/inet.c:icmpv6_nd_event()
> 2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
> connman/./connman/src/inet.c:icmpv6_nd_recv()
> 2015-09-17 05:46:57.000000 daemon.debug connmand[374]:
> connman/./connman/src/inet.c:icmpv6_nd_recv() code 198 len 62 hdr 24
> 2015-09-17 06:21:56.000000 daemon.info monit[483]: 'connmand' stop on
> user request
>
>
> Any help?
>
>
>
>
_______________________________________________
connman mailing list
connman@connman.net
https://lists.connman.net/mailman/listinfo/connman
