[Openstack] RPC timeout in nova-compute

Jiaan Zeng l.allen09 at gmail.com
Tue Aug 6 15:42:52 UTC 2013


I use a single node setup. The /var/log/rabbitmq-<hostname> log does
show some warnings e.g., "exception on TCP connection <0.13967.0> from
192.168.100.1:57097 connection_closed_abruptly". Below is the log
file. What does that exception mean?

=INFO REPORT==== 4-Aug-2013::16:39:00 ===
closing TCP connection <0.6353.1> from 192.168.100.1:57249

=INFO REPORT==== 4-Aug-2013::16:39:00 ===
closing TCP connection <0.13958.0> from 192.168.100.1:57092

=WARNING REPORT==== 4-Aug-2013::16:39:00 ===
exception on TCP connection <0.8253.2> from 192.168.100.1:57455
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:39:00 ===
closing TCP connection <0.8253.2> from 192.168.100.1:57455

=WARNING REPORT==== 4-Aug-2013::16:39:00 ===
exception on TCP connection <0.14191.0> from 192.168.100.1:57103
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:39:00 ===
closing TCP connection <0.14191.0> from 192.168.100.1:57103

=INFO REPORT==== 4-Aug-2013::16:39:01 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58251

=INFO REPORT==== 4-Aug-2013::16:39:01 ===
starting TCP connection <0.25306.109> from 192.168.100.1:58251

=INFO REPORT==== 4-Aug-2013::16:39:01 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58252

=INFO REPORT==== 4-Aug-2013::16:39:01 ===
starting TCP connection <0.25383.109> from 192.168.100.1:58252

=WARNING REPORT==== 4-Aug-2013::16:39:14 ===
exception on TCP connection <0.7516.2> from 192.168.100.1:57426
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:39:14 ===
closing TCP connection <0.7516.2> from 192.168.100.1:57426

=WARNING REPORT==== 4-Aug-2013::16:39:14 ===
exception on TCP connection <0.13967.0> from 192.168.100.1:57097
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:39:14 ===
closing TCP connection <0.13967.0> from 192.168.100.1:57097

=INFO REPORT==== 4-Aug-2013::16:39:14 ===
closing TCP connection <0.25306.109> from 192.168.100.1:58251

=WARNING REPORT==== 4-Aug-2013::16:39:14 ===
exception on TCP connection <0.25383.109> from 192.168.100.1:58252
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:39:14 ===
closing TCP connection <0.25383.109> from 192.168.100.1:58252

=INFO REPORT==== 4-Aug-2013::16:39:14 ===
closing TCP connection <0.15319.1> from 192.168.100.1:57346

=INFO REPORT==== 4-Aug-2013::16:39:14 ===
closing TCP connection <0.14119.0> from 192.168.100.1:57102

=WARNING REPORT==== 4-Aug-2013::16:39:14 ===
exception on TCP connection <0.13978.0> from 192.168.100.1:57098
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:39:14 ===
closing TCP connection <0.13978.0> from 192.168.100.1:57098

=WARNING REPORT==== 4-Aug-2013::16:39:15 ===
exception on TCP connection <0.13989.0> from 192.168.100.1:57099
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:39:15 ===
closing TCP connection <0.13989.0> from 192.168.100.1:57099

=INFO REPORT==== 4-Aug-2013::16:39:15 ===
closing TCP connection <0.14011.0> from 192.168.100.1:57101

=WARNING REPORT==== 4-Aug-2013::16:39:15 ===
exception on TCP connection <0.14000.0> from 192.168.100.1:57100
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:39:15 ===
closing TCP connection <0.14000.0> from 192.168.100.1:57100

=INFO REPORT==== 4-Aug-2013::16:39:15 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58253

=INFO REPORT==== 4-Aug-2013::16:39:15 ===
starting TCP connection <0.25600.109> from 192.168.100.1:58253

=INFO REPORT==== 4-Aug-2013::16:39:15 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58255

=INFO REPORT==== 4-Aug-2013::16:39:16 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58260

=INFO REPORT==== 4-Aug-2013::16:39:16 ===
starting TCP connection <0.25673.109> from 192.168.100.1:58260

=INFO REPORT==== 4-Aug-2013::16:39:16 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58262

=INFO REPORT==== 4-Aug-2013::16:39:16 ===
starting TCP connection <0.25699.109> from 192.168.100.1:58262

=INFO REPORT==== 4-Aug-2013::16:39:16 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58263

=INFO REPORT==== 4-Aug-2013::16:39:16 ===
starting TCP connection <0.25708.109> from 192.168.100.1:58263

=INFO REPORT==== 4-Aug-2013::16:39:16 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58264

=INFO REPORT==== 4-Aug-2013::16:39:16 ===
starting TCP connection <0.25730.109> from 192.168.100.1:58264

=INFO REPORT==== 4-Aug-2013::16:39:36 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58265

=INFO REPORT==== 4-Aug-2013::16:39:36 ===
starting TCP connection <0.26098.109> from 192.168.100.1:58265

=INFO REPORT==== 4-Aug-2013::16:41:07 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58276

=INFO REPORT==== 4-Aug-2013::16:41:07 ===
starting TCP connection <0.27137.109> from 192.168.100.1:58276

=INFO REPORT==== 4-Aug-2013::16:41:36 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58280

=INFO REPORT==== 4-Aug-2013::16:41:36 ===
starting TCP connection <0.27569.109> from 192.168.100.1:58280

=INFO REPORT==== 4-Aug-2013::16:54:49 ===
Changing password for 'guest'

=WARNING REPORT==== 4-Aug-2013::16:58:51 ===
exception on TCP connection <0.27137.109> from 192.168.100.1:58276
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:58:51 ===
closing TCP connection <0.27137.109> from 192.168.100.1:58276

=WARNING REPORT==== 4-Aug-2013::16:58:52 ===
exception on TCP connection <0.25609.109> from 192.168.100.1:58255
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:58:52 ===
closing TCP connection <0.25609.109> from 192.168.100.1:58255

=INFO REPORT==== 4-Aug-2013::16:58:52 ===
closing TCP connection <0.26098.109> from 192.168.100.1:58265

=INFO REPORT==== 4-Aug-2013::16:58:52 ===
closing TCP connection <0.25600.109> from 192.168.100.1:58253

=INFO REPORT==== 4-Aug-2013::16:58:52 ===
closing TCP connection <0.27569.109> from 192.168.100.1:58280

=WARNING REPORT==== 4-Aug-2013::16:58:52 ===
exception on TCP connection <0.25699.109> from 192.168.100.1:58262
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:58:52 ===
closing TCP connection <0.25699.109> from 192.168.100.1:58262

=INFO REPORT==== 4-Aug-2013::16:58:52 ===
closing TCP connection <0.25627.109> from 192.168.100.1:58259

=WARNING REPORT==== 4-Aug-2013::16:58:52 ===
exception on TCP connection <0.25618.109> from 192.168.100.1:58258
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:58:52 ===
closing TCP connection <0.25618.109> from 192.168.100.1:58258

=WARNING REPORT==== 4-Aug-2013::16:58:52 ===
exception on TCP connection <0.25673.109> from 192.168.100.1:58260
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:58:52 ===
closing TCP connection <0.25673.109> from 192.168.100.1:58260

=INFO REPORT==== 4-Aug-2013::16:58:52 ===
closing TCP connection <0.25730.109> from 192.168.100.1:58264

=WARNING REPORT==== 4-Aug-2013::16:58:52 ===
exception on TCP connection <0.25708.109> from 192.168.100.1:58263
connection_closed_abruptly

=INFO REPORT==== 4-Aug-2013::16:58:52 ===
closing TCP connection <0.25708.109> from 192.168.100.1:58263

=INFO REPORT==== 4-Aug-2013::16:58:52 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58286

=INFO REPORT==== 4-Aug-2013::16:58:52 ===
starting TCP connection <0.6987.110> from 192.168.100.1:58286

=INFO REPORT==== 4-Aug-2013::16:58:53 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58287

=INFO REPORT==== 4-Aug-2013::16:58:53 ===
starting TCP connection <0.6996.110> from 192.168.100.1:58287

=INFO REPORT==== 4-Aug-2013::16:58:53 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58290

=INFO REPORT==== 4-Aug-2013::16:58:53 ===
starting TCP connection <0.7018.110> from 192.168.100.1:58290

=INFO REPORT==== 4-Aug-2013::16:58:53 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58291

=INFO REPORT==== 4-Aug-2013::16:58:53 ===
starting TCP connection <0.7027.110> from 192.168.100.1:58291

=INFO REPORT==== 4-Aug-2013::16:58:53 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58295

=INFO REPORT==== 4-Aug-2013::16:58:53 ===
starting TCP connection <0.7107.110> from 192.168.100.1:58295

=INFO REPORT==== 4-Aug-2013::16:58:53 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58296

=INFO REPORT==== 4-Aug-2013::16:58:53 ===
starting TCP connection <0.7116.110> from 192.168.100.1:58296

=INFO REPORT==== 4-Aug-2013::16:59:27 ===
Limiting to approx 924 file handles (829 sockets)

=INFO REPORT==== 4-Aug-2013::16:59:27 ===
Memory limit set to 25741MB of 64354MB total.

=INFO REPORT==== 4-Aug-2013::16:59:27 ===
msg_store_transient: using rabbit_msg_store_ets_index to provide index

=INFO REPORT==== 4-Aug-2013::16:59:27 ===
msg_store_persistent: using rabbit_msg_store_ets_index to provide index

=WARNING REPORT==== 4-Aug-2013::16:59:27 ===
msg_store_persistent: rebuilding indices from scratch

=INFO REPORT==== 4-Aug-2013::16:59:27 ===
started TCP Listener on [::]:5672

=INFO REPORT==== 4-Aug-2013::16:59:28 ===
accepted TCP connection on [::]:5672 from 192.168.100.1:58320






On Mon, Aug 5, 2013 at 3:01 PM, Ritesh Nanda <riteshnanda09 at gmail.com> wrote:
> no i was taking about in case you have multi-node setup, can you share your
> /var/log/rabbitmq-<hostname> log , it must be showing something when you get
> rpc error in nova.
>
>
> On Mon, Aug 5, 2013 at 11:50 PM, Jiaan Zeng <l.allen09 at gmail.com> wrote:
>>
>> Hi Ritesh,
>>
>> I am not following. All the services run on a single node, i.e.,
>> compute node and control node co-locate. Do you mean I should remove
>> nova-conductor in a single node setup?
>>
>> The sql_connection string is as follows.
>> sql_connection=mysql://nova:nova@IP/nova
>>
>> On Mon, Aug 5, 2013 at 12:58 PM, Ritesh Nanda <riteshnanda09 at gmail.com>
>> wrote:
>> > Hello ,
>> >
>> > Please check nova-conductor should be not on the compute node , try
>> > mentioning sql_connection string in nova.conf on compute node.
>> >
>> >
>> > On Mon, Aug 5, 2013 at 3:45 PM, Somanchi Trinath-B39208
>> > <B39208 at freescale.com> wrote:
>> >>
>> >> Can you post the exact error from the nova log...
>> >>
>> >> --
>> >> Trinath Somanchi - B39208
>> >> trinath.somanchi at freescale.com | extn: 4048
>> >>
>> >> -----Original Message-----
>> >> From: Jiaan Zeng [mailto:l.allen09 at gmail.com]
>> >> Sent: Monday, August 05, 2013 7:49 AM
>> >> To: openstack at lists.openstack.org
>> >> Subject: [Openstack] RPC timeout in nova-compute
>> >>
>> >> Hi,
>> >>
>> >> I have been struggling on setting up quantum with grizzly for a long
>> >> time.
>> >> From nova-compute.log, I can see there is a RPC timeout error from
>> >> get_instance_nw_info() function in file
>> >> /usr/lib/python2.7/dist-packages/nova/network/api.py
>> >>
>> >> quantum-server is listening on 0.0.0.0:9696
>> >>
>> >> I already set network_api_class=nova.network.quantumv2.api.API. Isn't
>> >> the
>> >> get_instance_nw_info() function supposed to be in
>> >> /usr/lib/python2.7/dist-packages/nova/network/quantumv2/api.py?
>> >>
>> >> It seems nova compute is not picking up the network_api_class setting
>> >> although I restarted nova service after the configuration file was
>> >> changed.
>> >>
>> >> Any clues why this is happening? Thanks a lot.
>> >>
>> >> --
>> >> Regards,
>> >> Jiaan
>> >>
>> >> _______________________________________________
>> >> Mailing list:
>> >> http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack
>> >> Post to     : openstack at lists.openstack.org
>> >> Unsubscribe :
>> >> http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack
>> >>
>> >>
>> >>
>> >> _______________________________________________
>> >> Mailing list:
>> >> http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack
>> >> Post to     : openstack at lists.openstack.org
>> >> Unsubscribe :
>> >> http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack
>> >
>> >
>> >
>> >
>> > --
>> >
>> >  With Regards
>> >
>> >  Ritesh Nanda
>> >
>> >
>> >
>> >
>>
>>
>>
>> --
>> Regards,
>> Jiaan
>
>
>
>
> --
>
>  With Regards
>
>  Ritesh Nanda
>
>
>
>



-- 
Regards,
Jiaan




More information about the Openstack mailing list