20010207: McIDAS-XCD MDXX decoding problems (cont.)

>From: Leigh Orf <address@hidden>
>Organization: UNCA
>Keywords: 200102052335.f15NZkX27276 McIDAS-XCD

Leigh,

First off, I meant to send you back an email last night, but I kept
trying different things well into the morning all to no avail.  I
wanted to retract my suspicion about the problem being related to the
Linux 2.4 kernel and/or RH 7.0.

The reason for this is that I went out to another site running RH 6.2
and ran into the same problem.  That site is not running the latest
McIDAS-X addenda (they are still at 7.702), so I don't think that the
latest mods to m0raob have anything to do with what we are seeing.
Also, I tried doing the UAPLOT to storm2 from a McIDAS-X 7.613 session
and got the same results as from 7.7x.

>After reading your message I decided to try something else. I ran strace
>in front of mcserv on storm2 an put the output to a file. I think
>this is going to help us solve this. 

Excellent idea!

>There is a file called /tmp/mcserv-strace.out on storm2.  To generate
>the file I changed the last line of /home/mcidas/bin/mcservsh from
>
>exec $McINST_ROOT/bin/mcserv
>
>to
>
>exec strace -f -o /tmp/mcserv-strace.out $McINST_ROOT/bin/mcserv
>
>and tried to view a sounding from home once.

Good move.  I did the counterpart of this, I turned on tracing of the
server (vpserv) so that it would write out debug information while it
was procesing a remote Skew-T request from me (working at home from
a Mindspring ADSL connection).  The output in this file is equally
voluminous and not very illuminating to me.  It appears that the server
code merrily proceeds with processing even though the pipe to which
it is writing has been closed.

The real question is why the pipe is getting closed prematurely.

>The -f flag of strace traces all forked processes.
>
>Here's the juicy bits. Feel free to browse this monster file yourself:
>
>This starts at line 2555 of the file:

(some of the commentary I will include is for my benefit.  It will be useful
when looking back in the tracking system for similar problems.  Please
bear with me...)

The first bits you list are access to the actual data file:

>5785  access("/data/mcidas/data/MDXX0028", F_OK) = 0
>5785  lseek(4, 0, SEEK_END)             = 189696
>5785  lseek(4, 4, SEEK_SET)             = 4
>5785  read(4, "\2\0\0\0", 4)            = 4
 ...

Followed by the transaction through the pipe writing back to the client:

>5785  fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
>5785  rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0
>5785  write(1, "\0\0\0 ", 4)            = 4
>5779  <... read resumed> "\0\0\0 ", 4)  = 4
>5779  fstat(11, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
>5779  read(11,  <unfinished ...>
>5785  rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
>5785  fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
>5785  rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0
>5785  write(1, "SIGT\0\0n`\0\0h\350\0\0&z\0\1\32}\0\36\210\216\0\0\0\0"..., 32
> ) = 32
>5779  <... read resumed> "SIGT\0\0n`\0\0h\350\0\0&z\0\1\32}\0\36\210\216\0\0\0
> \0"..., 32) = 32
>5779  fstat(1, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
>5779  fcntl(1, F_GETFL)                 = 0x802 (flags O_RDWR|O_NONBLOCK)
>5779  select(2, NULL, [1], NULL, {120, 0}) = 1 (out [1], left {120, 0})

Everyting was OK right up until:

>5779  rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0
>5779  write(1, "\0\0\0H", 4)            = -1 EPIPE (Broken pipe)
>5779  --- SIGPIPE (Broken pipe) ---
>5779  rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
>5779  write(2, "sxsend: m0addewrite(           4"..., 49) = -1 EBADF (Bad file
>  descriptor)
>5779  _exit(0)                          = ?

This is where everything stops.  Now, on the client side, the loop that
is reading from the pipe gets a read error and issues a 'perror("pipe read")'.
As far as the client goes, everything is over, so the messages:

No observations found for selection conditions

SNDSKEWT: A sounding is not available in the dataset
UAPLOT:  Done

are displayed.  (As a quick aside here, UAPLOT is a "macro"; a program that
specifies defaults and then runs another program, SNDSKEWT.  This kind of
thing has a long history in McIDAS.  It is sometimes very useful, and other
times maddening.)

Back to the server side.  From the following, we can see that the server
is still trying to send data over the pipe that has been closed:

>5785  rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
>5785  fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
>5785  rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0
>5785  write(1, "\0\0\0 ", 4)            = -1 EPIPE (Broken pipe)
>5785  --- SIGPIPE (Broken pipe) ---
>5785  rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
>5785  write(2, "sxsend: m0addewrite(           4"..., 49) = -1 EBADF (Bad file
>  descriptor)
>5785  _llseek(2, 0, [0], SEEK_CUR)      = 0
>5785  fstat(2, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 3), ...}) = 0
>5785  _llseek(2, 0, [0], SEEK_END)      = 0
>5785  _llseek(2, 0, [0], SEEK_END)      = 0
>5785  fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
>5785  old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1
> , 0) = 0x40019000
>5785  _llseek(1, 0, 0xbfffe4e0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
>5785  fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
>5785  _llseek(1, 0, 0xbfffe4e0, SEEK_END) = -1 ESPIPE (Illegal seek)
>5785  _llseek(1, 0, 0xbfffe4e0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
>5785  _llseek(5, -20, [48], SEEK_CUR)   = 0
>5785  munmap(0x40018000, 4096)          = 0
>5785  _exit(0)                          = ?
>
>After that last command a bunch of 0x0's end up in the strace
>output... NOT GOOD. This should not happen.

Right.

>Broken pipes are bad. Bad file descriptors are bad...

I agree.

>Looks like the bad stuff starts here:
>
>5779  <... read resumed> 
>"SIGT\0\0n`\0\0h\350\0\0&z\0\1\32}\0\36\210\216\0\0\0\0"..., 32) = 32
>5779  fstat(1, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
>5779  fcntl(1, F_GETFL)                 = 0x802 (flags O_RDWR|O_NONBLOCK)
>5779  select(2, NULL, [1], NULL, {120, 0}) = 1 (out [1], left {120, 0})
>5779  write(1, "\0\0\0H", 4)            = -1 EPIPE (Broken pipe)
>5779  --- SIGPIPE (Broken pipe) ---
>5779  rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
>5779  write(2, "sxsend: m0addewrite(           4"..., 49) = -1 EBADF (Bad file
>  descriptor)
>5779  _exit(0)                          = ?
>
>Maybe finding out what sxsend does might help?

The code being executed is in ddesrvx.for:

       ! m0addewrite() - writes N bytes to a file descriptor, looping if
       ! necessary in the event of partial low-level writes.
       ! Also ignores SIGPIPE.
       integer          m0addewrite

       character*12     cfi
       integer          len_trim
       integer          m0syswrite

       nwritten = m0addewrite(1, buffer, nbytes)

       IF (nwritten .ne. nbytes) THEN
           ! an error message
           errmsg = 'sxsend: m0addewrite('//cfi(nbytes)//') = '
     &               //cfi(nwritten)//'\n'
           rc = m0syswrite(2, errmsg, len_trim(errmsg))

           STOP
       ENDIF

The failure here is a simple: compare attempt to write 'nbytes' with
how many were written, 'nwritten'.

I traced the write down to the following code:

ssize_t
M0writep(int fd, const void *buf,size_t nbyte)
{
        ssize_t         write_ans;      /* write() return code */
        int             write_errno;    /* write() errno setting */

        struct sigaction oldact;        /* saves SIGPIPE disposition */
        struct sigaction newact;        /* used to ignore SIGPIPE */

        /* Arrange to ignore the SIGPIPE signal. */

        newact.sa_handler = SIG_IGN;
        newact.sa_flags = 0;
        sigemptyset(&newact.sa_mask);

        if (sigaction(SIGPIPE, &newact, &oldact) == -1)
        {
                return -1;
        }

        /* Do the write. */

        write_ans = write(fd, buf, nbyte);
        write_errno = errno;

        /* Restore the signal dispositions. */

        if (sigaction(SIGPIPE, &oldact, (struct sigaction *) 0) == -1)
        {
                return -1;
        }

        /* Return the write() results. */

        errno = write_errno;
        return write_ans;
}

The sigaction call saves the current handling of SIGPIPE signals in
'oldact' and installs the 'newact' actions.  The newact actions are to
ignore SIGPIPE signals.

What is bothering me now is that the code says to ignore SIGPIPE signals;
then does a write _which fails with a SIGPIPE_!?

>Anyway the full files is there for you to browse. Let me know if this
>helps.

I have been perusing this for awhile now.  It is helping to really
understand the flow of the program, but I have not yet developed a
clear picture of what is happening.  The closest I have come is that

o a read on the pipe is done
o a select is done on open file descriptors waiting for a change
o a write is then attempted and it fails

It is as if the pipe wasn't ready for writing when the write proceeded.
And yet, this does not explain the EPIPE (broken pipe) error.

The other thing that bothers me is that this does not happen for other
ADDE transfers!?

I am developing a headache...

>From address@hidden Tue Feb  6 20:10:29 2001
>Subject: Re: 20010206: McIDAS-XCD MDXX decoding problems (cont.) 
>
>One more thing... my frazzled brain forgot to include this in my last
>message. I rebooted with kernel 2.2.18 - problem persists. The strace
>output is from the 2.2.18 kernel shortly after a reboot.

I was on when the reboot was done, but I failed to do a 'uname -a' to
see if a different kernel was being used.

>>From address@hidden Wed Feb  7 07:14:09 2001
>>Subject: thoughts
>
>Some more thoughts on this maddening problem:
>
>Do you know anyone else who is running an ADDE server on a red hat 7.0
>machine with all the recent updates?

No.  I am convinced now that it is not a RH 7.0 problem.

>I have a copy of RedHat 7.1beta that I am considering upgrading storm2
>to. Of course, in this case perhaps downgrading to a known working
>configuration is a better idea.

I don't think that this is warranted at the moment.

>Could perhaps some of the more recent updates to mcidas introduced a bug
>or two? I noticed some of the m0xxx routines where updated, along with
>sndskewt.

I don't think that anything was recently introduced.  Again, I cranked
up a 7.613 session on a Sun SPARC; pointed it at storm2; and got the
same problem.

I am getting suspicious of everything (CIA, KGB, NASA, etc ;-)

>After looking at the strace output, it occurs to me that perhaps it
>wasn't all that useful since all the bad things happen after that first
>SIGPIPE.

I think that it has been very useful for me to see the flow of transactions.
Please don't erase it just yet.  In fact, I may create another one on
a transaction that succeeds to see if that sheds any light on events.

>I think the EBADFs after that are responding to the fact that
>the file descriptor (which I assum is the pipe which is streaming data
>to the host) is no longer there.

I agree.

>Here are the versions of things currently on storm2:
>
>storm2[1004]:/home/mcidas/mcidas7.7/src% rpm -q glibc
>glibc-2.2-12
>storm2[1005]:/home/mcidas/mcidas7.7/src% rpm -q f2c
>f2c-20000510-4
>storm2[1006]:/home/mcidas/mcidas7.7/src% rpm -q gcc
>gcc-2.96-69

OK, thanks.  This may or may not be useful.

>plus:
>
>ldm-mcidas-7.6.4
>ldm-5.1.3
>mcidas7.7 + all recent updates (7.704)

The ldm-mcidas and LDM stuff should have no relation to the problem.

>I got ldm-mcidas and ldm in binary form. Perhaps building them from
>scratch is an option we should consider. Maybe it's something from the
>ldm that's stomping on the mcserv process. I have no clue.

I don't think so.  Please do not change either ldm-mcidas or the LDM
just now.  It would add too many new variables to deal with.

>It is so weird that only one routine is doing this, while I can grab any
>other form of data via the ADDE... from the same MDX files, too... I
>can do cross sections, upper level winds, etc. I think hodographs fail,
>too... let me check:
>
>HODO 72317 12 DAY=2001038 ANA=YES GRA=13 SF=YES
>NO WIND DATA AVAILABLE
>HODO:  Done

The fact that hodographs and soundings fail seems to be pointing to a
client problem.  I will pursue this avenue next.

>Yup. And when I do a DATALOC ADD RTPTSRC ADDE.UCAR.EDU everything comes
>up.

This is what originally led me to believe that the problem was a server
one.  It may well be a timing problem in the turning around of the pipe
for reads and writes.

>Ok, time to go to class...

Time for a new brain.  I will get back to you later with updates.

Tom

>From address@hidden Wed Feb  7 15:38:19 2001
>Subject: Re: 20010207: McIDAS-XCD MDXX decoding problems (cont.) 

Tom,

Not much new to report today. Thanks for the messsage BTW, your synopsis
of what is going on makes sense. I laughed when you said you were
suspicious of everything, CIA, FBI etc. :) These software problems can
make a person downright eyes-wide-open-at-3AM-trying-to-debug batty.

What I did discover today:

1) I *cannot* get a succesful skewt sounding to be generated when I have
strace in front of mcserv. Even if I'm on storm2! I imagine strace slows
things down, and this problem does appear to be related to timing. I can
sporadically get a good skewt if I remove the strace and request from
a machine on the local network. I can *never* get one from home where
there is a lot of latency and bandwidth cloggage between my cable modem
account and unca.

2) The garbage following the _exit(0) seems to only occur when I am
running from home. If I'm at work, the strace output file ends there.
See for instance /tmp/mc.out which is the output of an attempt to view
skewt data from work.

It is interesting that the fist broken pipe seems to *always* occur
after:

15192 write(1, "\0\0\0H", 4)            = -1 EPIPE (Broken pipe)

but maybe that's not interesting since that string is written a bunch of
times previous.

3) All other ADDE commands *don't* fail when the strace is in front
of mcserv. But one thing I noticed, which could be nothing, is that
successful mcserv sessions end with some illegal file seeks. For
instance, this is the end of a 500 mb plot of temperatures:

15552 rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
15552 _llseek(2, 0, [0], SEEK_CUR)      = 0
15552 fstat(2, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 3), ...}) = 0
15552 _llseek(2, 0, [0], SEEK_END)      = 0
15552 fstat(1, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
15552 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 
0) = 0x40019000
15552 _llseek(1, 0, 0xbffff8c0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
15552 fstat(1, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
15552 _llseek(1, 0, 0xbffff8c0, SEEK_END) = -1 ESPIPE (Illegal seek)
15552 _llseek(1, 0, 0xbffff8c0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
15552 _llseek(5, -20, [48], SEEK_CUR)   = 0
15552 munmap(0x40018000, 4096)          = 0
15552 _exit(0)                          = ?

I don't know if that's benign or not.

One other thing, I have done a dataloc.k RTPTSRC adde.ucar.edu for
typhoon and mac2 (not storm2).

Looks like this could be a tricky one to debug. I'm at least somewhat
glad that it's not due to my mcidas setup... that was getting pretty
frustrating.

It might be useful to compile mcidas with debugging (gcc -ggdb) and run
mcservsh from a debugger. Not sure how tricky it would be to do this
since mcserv is called from a script which is executed via inetd. I do
remember cases where I was debugging model code where running from the
debugger didn't help because what was *really* occurring was the program
was writing to a piece of memory it shouldn't (buffer overflow) which
can really be a pain to figure out especially if that memory segment
happens to lie where your debugger is :P

Anyway... I will leave things alone but keep storm2 running 2.2.18. I
can live with this problem although I would really love to see it
fixed... if there is anything I can do to help, let me know.

Leigh