Invalid inbound binary data should not be logged with %s, and probably not as ERROR

[cristalink]

Describe the bug

It appears my Asterisk is being probed for security vulnerabilities, and I am getting messages in the Asterisk log file like this one:

(1) The binary data dumped into the log file "as is" with %s is a bad practice for obvious reasons, It should be formatted as hex with printable ASCII and limited in length (e.g., to 64 or 128 bytes). The current code is below:

if (tmp.slen) { PJ_LOG(1, (THIS_FILE, "Error processing %ld bytes packet from %s %s:%d %.*s:\n" "%.*s\n" "-- end of packet.", msg_fragment_size, rdata->tp_info.transport->type_name, rdata->pkt_info.src_name, rdata->pkt_info.src_port, (int)tmp.slen, tmp.ptr, (int)msg_fragment_size, rdata->msg_info.msg_buf)); }

(2) It also shouldn't be logged as ERROR because at this level it's hard to get rid of these messages which in my case don't present an error at all but a nuisance. It could be logged as ERROR if it happened in a context of a valid connection. If it's just a random packet, it should be logged as a NOTICE or, better, DEBUG.

Thanks!

Steps to reproduce

N/A

PJSIP version

2.12.1, but the code is still present in master.

Context

N/A

Log, call stack, etc

N/A

[sauwming]

As this is SIP transport, we expect the packet received to be text and not binary.

As for the log level, since it's an error, level 1 seems to be appropriate.

What I can suggest is to filter the log by implementing your own log writer.
Alternatively, there's a callback tp_drop_data_cb(), which is currently called after the log is printed. I suppose we can change the order so that the callback is called first, and prevent the log from being printed under certain conditions.

[cristalink]

I'd log the error message as is, but without data, at the ERROR level. I'd log a second message with data at the DEBUG level.

The first (error) message can be used with fail2ban, to ban the IP addresses sending invalid packets.

The second (debug) message can be used for SIP troubleshooting. The hex format is appropriate to check for special symbols (such as '\n').

If one wants to see packets in plain text format, then "pjsip set logger on" in Asterisk would do.

Something like this:

[2023-04-04 10:58:23] ERROR[728152] pjproject: 	       sip_transport.c Error processing 340 bytes packet from UDP 127.0.0.1:53124 : PJSIP syntax error exception when parsing 'Request Line' header on line 1 col 1.
[2023-04-04 10:58:23] DEBUG[728152] pjproject: 	       sip_transport.c Error processing 340 bytes packet from UDP 127.0.0.1:53124 : PJSIP syntax error exception when parsing 'Request Line' header on line 1 col 1:
>0000: 5B 32 30 32 33 2D 30 34 - 2D 30 33 20 30 36 3A 32  [2023-04-03 06:2
>0010: 31 3A 35 39 5D 20 4E 4F - 54 49 43 45 5B 34 36 33  1:59] NOTICE[463
>0020: 37 34 5D 20 72 65 73 5F - 70 6A 73 69 70 2F 70 6A  74] res_pjsip/pj
>0030: 73 69 70 5F 64 69 73 74 - 72 69 62 75 74 6F 72 2E  sip_distributor.
>0040: 63 3A 20 52 65 71 75 65 - 73 74 20 27 52 45 47 49  c: Request 'REGI
>0050: 53 54 45 52 27 20 66 72 - 6F 6D 20 27 3C 73 69 70  STER' from '<sip
>0060: 3A 31 40 31 2E 32 2E 33 - 2E 34 3E 27 20 66 61 69  :1@1.2.3.4>' fai
>0070: 6C 65 64 20 66 6F 72 20 - 27 31 2E 32 2E 33 2E 34  led for '1.2.3.4
>0080: 3A 35 27 20 28 63 61 6C - 6C 69 64 3A 20 65 35 29  :5' (callid: e5)
>0090: 20 2D 20 46 61 69 6C 65 - 64 20 74 6F 20 61 75 74   - Failed to aut
>00A0: 68 65 6E 74 69 63 61 74 - 65 0A 5B 32 30 32 33 2D  henticate.[2023-
>00B0: 30 34 2D 30 33 20 30 36 - 3A 32 31 3A 35 39 5D 20  04-03 06:21:59] 
>00C0: 4E 4F 54 49 43 45 5B 34 - 36 33 37 34 5D 20 72 65  NOTICE[46374] re
>00D0: 73 5F 70 6A 73 69 70 2F - 70 6A 73 69 70 5F 64 69  s_pjsip/pjsip_di
>00E0: 73 74 72 69 62 75 74 6F - 72 2E 63 3A 20 52 65 71  stributor.c: Req
>00F0: 75 65 73 74 20 27 52 45 - 47 49 53 54 45 52 27 20  uest 'REGISTER' 
>0100: 66 72 6F 6D 20 27 3C 73 - 69 70 3A 31 40 31 2E 32  from '<sip:1@1.2
>0110: 2E 33 2E 34 3E 27 20 66 - 61 69 6C 65 64 20 66 6F  .3.4>' failed fo
>0120: 72 20 27 31 2E 32 2E 33 - 2E 34 3A 35 27 20 28 63  r '1.2.3.4:5' (c
>0130: 61 6C 6C 69 64 3A 20 65 - 35 29 20 2D 20 46 61 69  allid: e5) - Fai
>0140: 6C 65 64 20 74 6F 20 61 - 75 74 68 65 6E 74 69 63  led to authentic
>0150: 61 74 65 0A                                        ate.
-- end of packet.

The pjsip_tpmgr_receive_packet() function:

PJ_DEF(pj_ssize_t) pjsip_tpmgr_receive_packet( pjsip_tpmgr *mgr, pjsip_rx_data *rdata)
{
            . . .
            if (tmp.slen) {
                PJ_LOG(1, (THIS_FILE, 
				"Error processing %d bytes packet from %s %s:%d %.*s.",
				msg_fragment_size,
				rdata->tp_info.transport->type_name,
				rdata->pkt_info.src_name, 
				rdata->pkt_info.src_port,
				(int)tmp.slen, tmp.ptr));

                /* TODO: if (logLevel >= 4 ) */ {
                    char* data_string = data_to_string_with_malloc((unsigned)msg_fragment_size, rdata->msg_info.msg_buf);
                    if (data_string != NULL)
                    {
                        PJ_LOG(4, (THIS_FILE, 
                            "Error processing %d bytes packet from %s %s:%d %.*s:\n"
                            "%s"
                            "-- end of packet.",
                            msg_fragment_size,
                            rdata->tp_info.transport->type_name,
                            rdata->pkt_info.src_name, 
                            rdata->pkt_info.src_port,
                            (int)tmp.slen, tmp.ptr,
                            data_string));
                        free(data_string);
                    }
                }
        }

The logging function:

char* data_to_string_with_malloc(unsigned data_len, const void* data)
{
    /*           1         2         3         4         5         6         7         8    */
    /* 012345678901234567890123456789012345678901234567890123456789012345678901234567890 */
    /* >1234: 00 11 22 33 44 55 66 77 - 88 99 AA BB CC DD EE FF  0123456789ABCDEF\n     */

    const unsigned max_data_len = 0xFFFF;
    const unsigned max_string_len = 2048;

    const char* d;

    char* buf;
    char* pbuf;
    size_t szbuf;

    unsigned line;
    unsigned lines;
    unsigned offset;

    szbuf = max_string_len;
    buf = (char*) malloc(szbuf);
    if (buf == NULL)
    {
        return NULL;
    }

    pbuf = buf;

    d = (const char*)data;

    if (data_len > max_data_len)
    {
        data_len = max_data_len;
    }

    lines = (data_len + 15) / 16;

    for (line = 0; (line < lines) && (szbuf > 1); line++, d += 16)
    {
        int p;
        unsigned i;
        unsigned offset;
        unsigned cnt;

        offset = line * 16;

        cnt = data_len - offset;
        if (cnt > 16)
        {
            cnt = 16;
        }

        p = pj_ansi_snprintf(pbuf, szbuf, ">%04X: ", offset);	
        if (p < 0) goto on_error;
        pbuf += p;
        szbuf -= p;

        for (i = 0; i < 16; i++)
        {
            if(i == 8)
            {
                p = pj_ansi_snprintf(pbuf, szbuf, ((i < cnt) ? "- " : "  "));	
                if (p < 0) goto on_error;
                pbuf += p;
                szbuf -= p;
            }

            if (i < cnt)
            {
                p = pj_ansi_snprintf(pbuf, szbuf, "%02X ", d[i]);
            }
            else
            {
                p = pj_ansi_snprintf(pbuf, szbuf, "   ");
            }
            if (p < 0) goto on_error;
            pbuf += p;
            szbuf -= p;
        }

        p = pj_ansi_snprintf(pbuf, szbuf, " ");	
        if (p < 0) goto on_error;
        pbuf += p;
        szbuf -= p;

        for (i = 0; i < cnt; i++)
        {
            char c = d[i];
            if(!isprint(c))
            {
                c = '.';
            }

            p = pj_ansi_snprintf(pbuf, szbuf, "%c", c);	
            if (p < 0) goto on_error;
            pbuf += p;
            szbuf -= p;
        }

        p = pj_ansi_snprintf(pbuf, szbuf, "\n");	
        if (p < 0) goto on_error;
        pbuf += p;
        szbuf -= p;
    }

    return buf;

on_error:
    free(buf);
    return NULL;	
}

[sauwming]

Thanks for the proposed fix. For the ASCII printing, I will leave it to the user/app to do inside tp_drop_data_cb should they wish to do so.