<div dir="ltr"><div class="gmail_quote"><div dir="ltr"><p><span>Hi Folks,</span></p>
<p><span></span><br></p>
<p><span>Using libvirt python bindings we are creating an lxc container.Here is the problem that we see sometimes (say 20 % of the time) when we create a new container.</span></p>
<p><span></span><br></p>
<p><span>1.container gets created, and also starts.However the we are not able to enter the namepace of the container.It throws an error initPid not available.We see that the using netstat command , socket connection is closed.</span></p>
<p><span>2.To get around this problem we have to stop and start the container again.We see that socket under  (/var/run/libvirt/*) connection is established and we are able to enter the namespace.</span></p>
<p><span></span><br></p>
<p><span>Enabled the libvirtd debug logs to debug this issue.</span></p>
<p><span></span><br></p>
<p><span>For <b>success</b> case we see that for new client connection gets created and is able to handle async incoming events, </span></p>
<p><span></span><br></p>
<p><span><i>2016-03-12 08:18:55.748+0000: 1247: info : virObjectNew:202 : OBJECT_NEW: obj=0x7fed54005460 classname=virLXCMonitor</i></span></p>
<p><span><i>2016-03-12 08:18:55.748+0000: 1247: debug : virNetSocketNew:159 : localAddr=0x7fed7cd1d170 remoteAddr=0x7fed7cd1d200 fd=28 errfd=-1 pid=0</i></span></p>
<p><span><i>2016-03-12 08:18:55.749+0000: 1247: info : virObjectNew:202 : OBJECT_NEW: obj=0x7fed54009040 classname=virNetSocket</i></span></p>
<p><span><i>2016-03-12 08:18:55.749+0000: 1247: info : virNetSocketNew:209 : RPC_SOCKET_NEW: sock=0x7fed54009040 fd=28 errfd=-1 pid=0 localAddr=127.0.0.1;0, remoteAddr=127.0.0.1;0</i></span></p>
<p><span><i>2016-03-12 08:18:55.749+0000: 1247: info : virObjectNew:202 : OBJECT_NEW: obj=0x7fed54009d10 classname=virNetClient</i></span></p>
<p><span><i>2016-03-12 08:18:55.749+0000: 1247: info : virNetClientNew:327 : RPC_CLIENT_NEW: client=0x7fed54009d10 sock=0x7fed54009040</i></span></p>
<p><span><i>2016-03-12 08:18:55.749+0000: 1247: info : virObjectRef:296 : OBJECT_REF: obj=0x7fed54009d10</i></span></p>
<p><span><i>2016-03-12 08:18:55.749+0000: 1247: info : virObjectRef:296 : OBJECT_REF: obj=0x7fed54009040</i></span></p>
<p><span><i><b>2016-03-12 08:18:55.750+0000: 1247: info : virObjectNew:202 : OBJECT_NEW: obj=0x7fed540009a0 classname=virNetClientProgram</b></i></span></p>
<p><span><i>2016-03-12 08:18:55.750+0000: 1247: info : virObjectRef:296 : OBJECT_REF: obj=0x7fed540009a0</i></span></p>
<p><span><i>2016-03-12 08:18:55.750+0000: 1247: info : virObjectRef:296 : OBJECT_REF: obj=0x7fed54005460</i></span></p>
<p><span><i>2016-03-12 08:18:55.750+0000: 1247: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7fed5c168eb0</i></span></p>
<p><span><i>2016-03-12 08:18:55.750+0000: 1247: debug : virLXCProcessCleanInterfaces:475 : Cleared net names: eth0 </i></span></p>
<p><span><i>2016-03-12 08:18:55.750+0000: 1247: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7fed5c168eb0</i></span></p>
<p><span><i>2016-03-12 08:18:55.750+0000: 1247: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7fed5c169600</i></span></p>
<p><span><i>2016-03-12 08:18:55.755+0000: 1244: debug : virNetClientIncomingEvent:1808 : client=0x7fed54009d10 wantclose=0</i></span></p>
<p><span><i>2016-03-12 08:18:55.755+0000: 1244: debug : virNetClientIncomingEvent:1816 : Event fired 0x7fed54009040 1</i></span></p>
<p><span><i>2016-03-12 08:18:55.755+0000: 1244: debug : virNetMessageDecodeLength:151 : Got length, now need 36 total (32 more)</i></span></p>
<p><span><i>2016-03-12 08:18:55.756+0000: 1244: info : virNetClientCallDispatch:1116 : RPC_CLIENT_MSG_RX: client=0x7fed54009d10 len=36 prog=305402420 vers=1 proc=2 type=2 status=0 serial=1</i></span></p>
<p><span><i>2016-03-12 08:18:55.756+0000: 1244: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fed81fc5ed4, msg=0x7fed54009d78</i></span></p>
<p><span><i>2016-03-12 08:18:55.756+0000: 1244: debug : virNetClientProgramDispatch:220 : prog=305402420 ver=1 type=2 status=0 serial=1 proc=2</i></span></p>
<p><span><i>2016-03-12 08:18:55.756+0000: 1244: debug : virLXCMonitorHandleEventInit:109 : Event init 1420 </i></span></p>
<p><span></span><br></p>
<p><span>For <b>failure</b> case ,we see that the client socket connection is initiated and gets closed immediately after receiving an incoming event.In this case, I don’t see an object for virNetClientProgram being created.</span></p>
<p><span>Incoming event comes in and since the its unable to find client->prog it bails out and closes the connection.</span></p>
<p><span>Snaphost of the code,</span></p>
<p><span></span><br></p>
<p><span>static int virNetClientCallDispatchMessage(virNetClientPtr client)</span></p>
<p><span>{</span></p>
<p><span>    size_t i;</span></p>
<p><span>    virNetClientProgramPtr prog = NULL;</span></p>
<p><span></span><br></p>
<p><span>    for (i = 0; i < client->nprograms; i++) {</span></p>
<p><span>        if (virNetClientProgramMatches(client->programs[i],</span></p>
<p><span>                                       &client->msg)) {</span></p>
<p><span>            prog = client->programs[i];</span></p>
<p><span>            break;</span></p>
<p><span>        }</span></p>
<p><span>    }    </span></p>
<p><span>    if (!prog) {</span></p>
<p><span><b>        VIR_DEBUG("No program found for event with prog=%d vers=%d",</b></span></p>
<p><span><b>                  client->msg.header.prog, client->msg.header.vers);</b></span></p>
<p><span>        return -1;</span></p>
<p><span>    } </span></p>
<p><span></span><br></p>
<p><span><i>2016-03-12 08:19:15.935+0000: 1246: info : virObjectRef:296 : OBJECT_REF: obj=0x7fed5c168eb0</i></span></p>
<p><span><i>2016-03-12 08:19:15.935+0000: 1246: info : virObjectRef:296 : OBJECT_REF: obj=0x7fed82bd7bc0</i></span></p>
<p><span><i>2016-03-12 08:19:15.935+0000: 1246: info : virObjectNew:202 : OBJECT_NEW: obj=0x7fed82bd8120 classname=virLXCMonitor</i></span></p>
<p><span><i>2016-03-12 08:19:15.935+0000: 1246: debug : virNetSocketNew:159 : localAddr=0x7fed7d51e170 remoteAddr=0x7fed7d51e200 fd=31 errfd=-1 pid=0</i></span></p>
<p><span><i>2016-03-12 08:19:15.936+0000: 1246: info : virObjectNew:202 : OBJECT_NEW: obj=0x7fed82bd8660 classname=virNetSocket</i></span></p>
<p><span><i>2016-03-12 08:19:15.936+0000: 1246: info : virNetSocketNew:209 : RPC_SOCKET_NEW: sock=0x7fed82bd8660 fd=31 errfd=-1 pid=0 localAddr=127.0.0.1;0, remoteAddr=127.0.0.1;0</i></span></p>
<p><span><i>2016-03-12 08:19:15.936+0000: 1246: info : virObjectNew:202 : OBJECT_NEW: obj=0x7fed82bd8ca0 classname=virNetClient</i></span></p>
<p><span><i>2016-03-12 08:19:15.936+0000: 1246: info : virNetClientNew:327 : RPC_CLIENT_NEW: client=0x7fed82bd8ca0 sock=0x7fed82bd8660</i></span></p>
<p><span><i>2016-03-12 08:19:15.936+0000: 1246: info : virObjectRef:296 : OBJECT_REF: obj=0x7fed82bd8ca0</i></span></p>
<p><span><i>2016-03-12 08:19:15.936+0000: 1246: info : virObjectRef:296 : OBJECT_REF: obj=0x7fed82bd8660</i></span></p>
<p><span><b><i>2016-03-12 08:19:15.942+0000: 1244: debug : virNetClientIncomingEvent:1808 : client=0x7fed82bd8ca0 wantclose=0</i></b></span></p>
<p><span><b><i>2016-03-12 08:19:15.942+0000: 1244: debug : virNetClientIncomingEvent:1816 : Event fired 0x7fed82bd8660 1</i></b></span></p>
<p><span><i>2016-03-12 08:19:15.942+0000: 1244: debug : virNetMessageDecodeLength:151 : Got length, now need 36 total (32 more)</i></span></p>
<p><span><i>2016-03-12 08:19:15.942+0000: 1244: info : virNetClientCallDispatch:1116 : RPC_CLIENT_MSG_RX: client=0x7fed82bd8ca0 len=36 prog=305402420 vers=1 proc=2 type=2 status=0 serial=1</i></span></p>
<p><span><i>2016-03-12 08:19:15.942+0000: 1244: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fed81fc5ed4, msg=0x7fed82bd8d08</i></span></p>
<p><span><b><i>2016-03-12 08:19:15.942+0000: 1244: debug : virNetClientCallDispatchMessage:1008 : No program found for event with prog=305402420 vers=1</i></b></span></p>
<p><span><i>2016-03-12 08:19:15.942+0000: 1244: debug : virNetMessageClear:57 : msg=0x7fed82bd8d08 nfds=0</i></span></p>
<p><span><b><i>2016-03-12 08:19:15.942+0000: 1244: debug : virNetClientMarkClose:632 : client=0x7fed82bd8ca0, reason=0</i></b></span></p>
<p><span><b><i>2016-03-12 08:19:15.942+0000: 1244: debug : virNetClientCloseLocked:648 : client=0x7fed82bd8ca0, sock=0x7fed82bd8660, reason=0</i></b></span></p>
<p><span></span><br></p>
<p><span></span><br></p>
<p><span>Here is the snapshot of code ,</span></p>
<p><span></span><br></p>
<p><span>virLXCMonitorPtr virLXCMonitorNew(virDomainObjPtr vm, </span></p>
<p><span>                                  const char *socketdir,</span></p>
<p><span>                                  virLXCMonitorCallbacksPtr cb) </span></p>
<p><span>{</span></p>
<p><span>    virLXCMonitorPtr mon;</span></p>
<p><span>    char *sockpath = NULL;</span></p>
<p><span></span><br></p>
<p><span>    if (virLXCMonitorInitialize() < 0)</span></p>
<p><span>        return NULL;</span></p>
<p><span></span><br></p>
<p><span>    if (!(mon = virObjectLockableNew(virLXCMonitorClass)))</span></p>
<p><span>        return NULL;</span></p>
<p><span></span><br></p>
<p><span>    if (virAsprintf(&sockpath, "%s/%s.sock",</span></p>
<p><span>                    socketdir, vm->def->name) < 0)</span></p>
<p><span>        goto error;</span></p>
<p><span></span><br></p>
<p><span>    if (!(mon->client = virNetClientNewUNIX(sockpath, false, NULL)))</span></p>
<p><span>        goto error;</span></p>
<p><span></span><br></p>
<p><span>   </span><span><b> if (virNetClientRegisterAsyncIO(mon->client) < 0)</b></span></p>
<p><span><b>        goto error;</b></span></p>
<p><span><b></b></span><br></p>
<p><span><b>    if (!(mon->program = virNetClientProgramNew(VIR_LXC_MONITOR_PROGRAM,</b></span></p>
<p><span><b>                                                VIR_LXC_MONITOR_PROGRAM_VERSION,</b></span></p>
<p><span><b>                                                virLXCMonitorEvents,</b></span></p>
<p><span><b>                                                ARRAY_CARDINALITY(virLXCMonitorEvents),</b></span></p>
<p><span><b>                                                mon)))</b></span></p>
<p><span><b>        goto error;</b></span></p>
<p><span><b></b></span><br></p>
<p><span><b>    if (virNetClientAddProgram(mon->client,</b></span></p>
<p><span><b>                               mon->program) < 0)</b></span></p>
<p><span><b>        goto error;</b></span></p>
<p><span><b></b></span><br></p>
<p><span><b>    mon->vm = vm;</b></span></p>
<p><span><b>    memcpy(&mon->cb, cb, sizeof(mon->cb));</b></span></p>
<p><span></span><br></p>
<p><span>    virObjectRef(mon);</span></p>
<p><span>    virNetClientSetCloseCallback(mon->client, virLXCMonitorEOFNotify, mon,</span></p>
<p><span>                                 virLXCMonitorCloseFreeCallback);</span></p>
<p><span></span><br></p>
<p><span>Is the problem occurring due to invocation of  “<b>virNetClientRegisterAsyncIO" api before the virNetClientAddProgram.Probably once we register for aysnc IO , immediately an event comes in and that thread takes priority and bails out since it does not find the client->prog?Also the client is not retrying to establish a new connection.</b></span></p>
<p><span><b></b></span><br></p>
<p><span><b>Please let me any thoughts/comments.Is there any patch already available which has fixed this issue?We are using libvirt 1.2.15</b></span></p>
<p><span><b></b></span><br></p>
<p><span><b>-Thanks,</b></span></p>
<p><span><b>Rammohan</b></span></p></div>
</div><br></div>