Cellular Network Infrastructure » OsmoMGW

The decisive output is:

[  105s] Regression tests.
[  105s] 
[  105s]   1: legacy_mgcp                                     ok
[  105s]   2: legacy_mgcp-trans                               skipped (testsuite.at:12)
[  105s]   3: mgcp_client                                     ok
[  105s]   4: mgcp                                            FAILED (testsuite.at:27)

But I cannot reproduce the mgcp test failure.

The OBS builds (still) don't output the test logs and I am not sure how we can obtain them.
Something like the cat-testlogs.sh our jenkins builds are doing would be very helpful.
https://git.osmocom.org/osmo-ci/tree/scripts/cat-testlogs.sh

I would like to redirect to lynxis to probe whether we can get the test logs, and to dexter for an mgcp_test.c fix.

neels: I've extended the log similiar to libosmocore [1]. I've manual deployed this patch to OBS. [1] or attached log.txt now shows the exact problem.

dexter: can you take a look on the test output?

[1] https://gerrit.osmocom.org/#/c/4212/
[2] https://build.opensuse.org/build/network:osmocom:nitb-split:nightly/Debian_9.0/x86_64/osmo-mgw/_log

I am sorry, without further information such as log outputs I can not help much.

dexter, there is a link right there with log outputs, you should have been able to investigate.

anyway, here is one again https://build.opensuse.org/package/live_build_log/network:osmocom:nitb-split:nightly/osmo-mgw/xUbuntu_16.10/x86_64
which was also posted on the chat. So it seems like you have other reasons to not look into this.

thx

It seems that it is a problem with the override of sendto(). I also wonder why
the legacy test does not fail since it is very similar to the mgcp test that
fails. If the following solution works out we might want to apply it there
as well.

In mgcp_test.c one can find an override of sendto:

#define MGCP_DUMMY_LOAD 0x23
static int dummy_packets = 0;
/* override and forward */
ssize_t sendto(int sockfd, const void *buf, size_t len, int flags,
        const struct sockaddr *dest_addr, socklen_t addrlen)
{
    typedef ssize_t (*sendto_t)(int, const void *, size_t, int,
            const struct sockaddr *, socklen_t);
    static sendto_t real_sendto = NULL;
    uint32_t dest_host = htonl(((struct sockaddr_in *)dest_addr)->sin_addr.s_addr);
    int      dest_port = htons(((struct sockaddr_in *)dest_addr)->sin_port);

    if (!real_sendto)
        real_sendto = dlsym(RTLD_NEXT, "sendto");

    if (len == 1 && ((const char *)buf)[0] == MGCP_DUMMY_LOAD ) {
        fprintf(stderr, "Dummy packet to 0x%08x:%d, msg length %zu\n%s\n\n",
               dest_host, dest_port,
               len, osmo_hexdump(buf, len));
        dummy_packets += 1;
    }

    return real_sendto(sockfd, buf, len, flags, dest_addr, addrlen);
}

I have problems to understand this. There is a function pointer real_sendto
that is set to NULL, only to detect a few lines later that it is really NULL
and populate it then with the symbol of the sendto (the real sendto). However,
this happens only once and real_sendto is static. Its either a lengthy process
or it must not happen twice - however.

The interesting part is that the override sendo is counting the transmitted
dummy packets.

After the counting the packets are forwared using the real_sendto. This is
why we see the packets in wireshark. Probably we want to remove this so that
no actual packets leave. At least when I comment the real_sendto out the
test still passes. So that would be a way to get rid of the packets that
OBS probably won't like.

Lets have a look at the log output:

[   80s] <0010> mgcp_network.c:136 endpoint:5 Failed to send dummy RTP packet.
[   80s] [0;m<0010> mgcp_protocol.c:747 CRCX: endpoint:5 connection successfully created
[   80s] [0;m<0010> mgcp_protocol.c:522 CRCX: creating new connection ...
[   80s] [0;m<0010> mgcp_sdp.c:300 Got media info via SDP: port 5904, payload 97 (GSM-EFR), duration 40, addr 123.12.12.123
[   80s] [0;mPolicy CB got state 1 on endpoint 1
[   80s] Dummy packet to 0x7b0c0c7b:5904, msg length 1
[   80s] 23 
[   80s] 
[   80s] <0010> mgcp_network.c:136 endpoint:1 Failed to send dummy RTP packet.
[   80s] [0;m<0010> mgcp_protocol.c:747 CRCX: endpoint:1 connection successfully created
[   80s] [0;m<0010> mgcp_osmux.c:682 All Osmux circuits are in use!
[   80s] [0;m--- expout    2017-10-13 13:15:05.388398199 +0000
[   80s] +++ /usr/src/packages/BUILD/tests/testsuite.dir/at-groups/4/stdout    2017-10-13 13:15:05.436398197 +0000
[   80s] @@ -16,12 +16,12 @@
[   80s]  Testing MDCX1
[   80s]  Testing MDCX2
[   80s]  Testing CRCX
[   80s] -Dummy packets: 2
[   80s] +Dummy packets: 1

We can see that the sendto() override is executed. Then we spot a message
from mgcp_network.c. This could mean that the dummy sendto returned with
an error code. Probably because the real_sendto returned an eror.

The dummy packet transmission terminates on this function:

int mgcp_send_dummy(struct mgcp_endpoint *endp, struct mgcp_conn_rtp *conn)
{
    static char buf[] = { MGCP_DUMMY_LOAD };
    int rc;
    int was_rtcp = 0;

    OSMO_ASSERT(endp);
    OSMO_ASSERT(conn);

    LOGP(DLMGCP, LOGL_DEBUG,
         "endpoint:%x sending dummy packet...\n", ENDPOINT_NUMBER(endp));
    LOGP(DLMGCP, LOGL_DEBUG, "endpoint:%x conn:%s\n",
         ENDPOINT_NUMBER(endp), mgcp_conn_dump(conn->conn));

    rc = mgcp_udp_send(conn->end.rtp.fd, &conn->end.addr,
               conn->end.rtp_port, buf, 1);

    if (rc == -1)
        goto failed;

    if (endp->tcfg->omit_rtcp)
        return rc;

    was_rtcp = 1;
    rc = mgcp_udp_send(conn->end.rtcp.fd, &conn->end.addr,
               conn->end.rtcp_port, buf, 1);

    if (rc >= 0)
        return rc;

failed:
    LOGP(DLMGCP, LOGL_ERROR,
         "endpoint:%x Failed to send dummy %s packet.\n",
         ENDPOINT_NUMBER(endp), was_rtcp ? "RTCP" : "RTP");

    return -1;
}

Here we can see that the mgcp_udp_send() should normally execute twice. This
matches the observed behaviour. We see the output from the sendto() override,
wich executes ok until the point where it outputs. We also count the
dummy_packets one up.

Probably the real_sendto at the end of the sendto() override fails. This
eventually leads into a bad return code of mgcp_udp_send() and we will send
to failed: This is why we see the error message immediately after. By this
we omit the second mgcp_udp_send(), which would normally give us the second
dummy dummy packet.

Since the test still passes when the real_sendto is removed we possibly may
try this. A patch is available for review: https://gerrit.osmocom.org/4260

dexter wrote:

I have problems to understand this. There is a function pointer real_sendto
that is set to NULL, only to detect a few lines later that it is really NULL
and populate it then with the symbol of the sendto (the real sendto). However,
this happens only once and real_sendto is static. Its either a lengthy process
or it must not happen twice - however.

The code doesn't want to load the symbol using the dynamic linker more than once.
What I, too, fail to understand is why the test goes to all this trouble when
removing this doesn't seem to affect the test in the slightest.

The interesting part is that the override sendo is counting the transmitted
dummy packets. [...] we see the error message [...] would normally give us the second
dummy dummy packet.

Indeed, this should be the actual cause.
Let's try to clarify why the test was even sending out packets in the first place.
Ask zecke??

I will drop the dummy packets completely as demanded in #2574. I wrote Holger an Email since we potentially have the same problem in legacy_mgcp as well.

neels wrote:

The code doesn't want to load the symbol using the dynamic linker more than once.
What I, too, fail to understand is why the test goes to all this trouble when
removing this doesn't seem to affect the test in the slightest.

We want to observe the side-effect (and we don't want to have a "network interface" indirection in the code).

neels Is the problem still present?

dexter wrote:

neels Is the problem still present?

Patch is merged, and osmo-mgw builds successfully, as can be seen at https://build.opensuse.org/project/show/network:osmocom:nitb-split:nightly

Do we have a conclusion yet on whether we should re-add sending of packets in the test?
Personally, I would keep them disabled, and refer to Harald's TTCN3 setup to test for network operation related leaks and side effects.
zecke, would that be ok from your viewpoint?

no feedback about re-enabling the sendign in the unit tests, let's close this.