initctl unable to communicate with init

[Chris Packham]

On Mon, May 3, 2010 at 9:57 AM, Chris Packham <judge.packham at gmail.com> wrote:
> Hi,
>
> We've been using upstart in our embedded products for some time now
> (we're using upstart 0.5.1). I'm in the process of porting our
> software to a new hardware platform and I'm running into a problem
> thats got me stumped.
>
> Our first init script mounts the file systems and then uses "initctl
> reload" to reload the upstart config from the on-flash upstart config.
> The problem is that "initctl reload" just hangs waiting forever. As
> far as I've been able to debug so far it seems to be in the dbus
> message dispatch which should have sent the message to init. I think
> its waiting for a response it never sees, I also think init never got
> the message.
>
> I've run the same code on one of our existing platforms and that
> starts up normally so I'm thinking its a toolchain/kenrel setup issue
> but the only differences I can see in that area are the things that
> _are_ different.
>
> The platforms I'm using are as follows
>
> Existing platform (works): PowerPC e300(603e) core, Linux 2.6.32.12,
> uClibc 0.9.30.1, gcc 4.3.3
> New platform (doesn't work): PowerPC e500 core, Linux 2.6.32.12,
> uClibc 0.9.30.1, gcc 4.3.3
>
> Thanks,
> Chris
>

Hi,

Just thought I'd ping the list with an update of my thus far
unsuccessful debugging in case it rings some bells for someone. (BTW
whats this lists practice on CCing, I've CC'd Scott and Kees because
they'd both responded earlier but I wasn't entirely sure that I
should).

Mounting tmpfs before running init didn't have any noticeable impact.
Looks like despite not having a working rtc the time related system
calls are still ticking away. As far as I can tell all the kernel
options are right to enable socket based IPC. I've written a really
simple test program and verified that it is possible for a server and
client to communicate via a unix socket, I'll beef that program up a
bit and fire up a few more sockets and a few more clients

I've captured some strace output which I'll post some snippets of
below. Its pretty much as I'd said earlier initctl is waiting for a
response from the reload message and never sees it. Here's the strace
output, I'll add my own commentary prefixed with CP>.

strace -f /sbin/init
execve("/sbin/init", ["/sbin/init"], [/* 6 vars */]) = 0
open("/dev/urandom", O_RDONLY)          = 3
read(3, "\272LFT"..., 4)                = 4
close(3)                                = 0
<snip>
socket(PF_FILE, SOCK_STREAM, 0)         = 6
bind(6, {sa_family=AF_FILE, path=@"/com/ubuntu/upstart"...}, 22) = 0
listen(6, 30)                           = 0
fcntl64(6, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl64(6, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
fcntl64(6, F_GETFD)                     = 0
fcntl64(6, F_SETFD, FD_CLOEXEC)         = 0

CP> OK so thats init opening the unix socket /com/ubuntu/upstart to
listen on, so far so good.

<snip>
write(1, "Starting base/first...           "..., 75Starting
base/first...                                  [  OK  ]
) = 75
write(4, "\0"..., 1)                    = 1
brk(0x1005a000)                         = 0x1005a000
stat64("/dev/fd", 0xbfbf9450)           = -1 ENOENT (No such file or directory)
pipe([7, 8])                            = 0
rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0
fork()                                  = 977
Process 977 attached

CP> If I understand correctly this is init forking a process for the
"base/first" job.

[pid   977] close(7)                    = 0
[pid   977] fcntl64(8, F_GETFD)         = 0
[pid   977] fcntl64(8, F_SETFD, FD_CLOEXEC) = 0
[pid   977] setsid()                    = 977
[pid   977] fork()                      = 978
Process 978 attached
[pid   977] exit(0)                     = ?
Process 977 detached

CP> not sure about this but I guess thats the base/first job forking
to run the script stanza

<snip>
[pid   978] write(1, "reloading upstart config ... "..., 29reloading
upstart config ... ) = 29
[pid   978] stat64("/sbin/initctl", {st_mode=S_IFREG|0755,
st_size=66272, ...}) = 0
[pid   978] fork()                      = 1017
Process 1017 attached
[pid   978] wait4(-1, <unfinished ...>
Process 978 suspended
[pid  1017] rt_sigaction(SIGQUIT, {SIG_DFL, [HUP RT_4 RT_5 RT_6 RT_8
RT_10 RT_13 RT_16 RT_17 RT_18 RT_19 RT_20 RT_28 RT_31],
SA_RESTART|0x874a8}, NULL, 8) = 0
[pid  1017] execve("/sbin/initctl", ["initctl", "reload"], [/* 5 vars */]) = 0
[pid  1017] open("/dev/urandom", O_RDONLY) = 3
[pid  1017] read(3, "\n\1\336\370"..., 4) = 4
[pid  1017] close(3)                    = 0

CP> Thats initctl firing up

[pid  1017] socket(PF_FILE, SOCK_STREAM, 0) = 3
[pid  1017] connect(3, {sa_family=AF_FILE,
path=@"/com/ubuntu/upstart"...}, 22) = 0
[pid  1017] fcntl64(3, F_GETFL)         = 0x2 (flags O_RDWR)
[pid  1017] fcntl64(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
[pid  1017] fcntl64(3, F_GETFD)         = 0
[pid  1017] fcntl64(3, F_SETFD, FD_CLOEXEC) = 0

CP> initctl opening /com/ubuntu/upstart

<snip>
[pid  1017] brk(0x10023000)             = 0x10023000
[pid  1017] time(NULL)                  = 83
[pid  1017] poll([{fd=3, events=POLLOUT}], 1, 0) = 1 ([{fd=3, revents=POLLOUT}])
[pid  1017] write(3, "\0"..., 1)        = 1
[pid  1017] write(3, "AUTH EXTERNAL 30\r\n"..., 18) = 18
[pid  1017] write(5, "\0"..., 1)        = 1
[pid  1017] poll([{fd=3, events=POLLIN}], 1, -1

CP> This is where things stop. Process 978 (base/first script stanza)
is waiting for Process 1017 (initctl) to finish. Initctl is waiting
for a response to be received from the /com/ubuntu/upstart socket. As
far as I can see init is dutifully listening on that socket but as you
can see from the trace init never received the message (I don't know
if strace would show me that it got resumed unless it actually made
another system call).

Thanks,
Chris