Logging to syslog from remote host -- "Invalid PRI"

F

free-and-bsd

Hi everyone. It's been a while since I wrote here...
Anyway, I'm trying to set up my host syslogd to accept remote logging from an IP phone (Grandstream GXP1450). Followed guidance from here, step by step, but this is what I get in the onscreen debug output after adding -d option to the start command (because nothing gets logged):
Code: 
# of validation rule: 1
validate: dgram from IP 192.X.X.X, port 56109, name ${myname}.;
accepted in rule 1.
Invalid PRI from ${myname}
received sa_len = 16
cvthname(2) len = 16
cvthname(192.168.8.204)
And I can find NOTHING on the web about this strange rejection reply "Invalid PRI", nor any idea how to fix it or make syslogd ignore this. Whatever is that PRI, it is obviously generated to IP phone itself, and I have no control over that, alas. No telnet/ssh access, only the GUI.

Could anybody, please, suggest anything? There are not many controls in theI P phone web-UI (and none other available) related to logging -- it's only "syslog server" box for FQDN/IP and drop-down menu "log level" with standard log levels.

PF log shows logging from the phone's IP is accepted, but none is logged, and when I restart syslogd with that debug command line option (in /etc/rc.conf), as mentioned in the docs, I get the above... :(
 
What syslogd is telling you is that the other side (the IP phone) is sending you an invalid message. Namely, the PRI part of the message is formatted wrong.

Suggestion: Open the RFC for syslog, and read and understand the packet = message format in the RFC. Then run tcpdump on the host that has the syslogd server, and dump the complete syslog packet in hex and ASCII. Decode it by hand, and look at the PRI field. Compare what you find to the RFC.
 
free-and-bsd said:
Whatever is that PRI, it is obviously generated to IP phone itself, and I have no control over that, alas. No telnet/ssh access, only the GUI.
Click to expand...

I've heard that PRI already, just can'r remember. And an IP phone, I would suppose, it's just another broken linux implementation in a closed-shop plastic box?

So, lets use the source: usr.sbin/syslogd/syslogd.c:
Code: 
 * Takes a raw input line, extracts PRI and determines whether the
 * message is formatted according to RFC 3164 or RFC 5424. Continues
 * parsing of addition fields in the message according to those
 * standards and prints the message on the appropriate log files.
 */
static void
parsemsg(const char *from, char *msg)
{
        char *q;
        long n;
        size_t i;
        int pri;

        /* Parse PRI. */
        if (msg[0] != '<' || !isdigit(msg[1])) {
                dprintf("Invalid PRI from %s\n", from);
                return;
        }

So, whatever that IP phone sends, it seems the first char is not a "<" or the second is not a digit.
When doing tcpdump -A, that "PRI" is visible right before the actual message:
................... ........<37>Aug 2 22:11:50 syslogd: last message repeated 1 times
It appears to be a decimal number within <>, encoding one byte, with 32 facilities each having 8 priorities
 
Thanks a lot! Unfortunately, there's no control over what the IP phone is sending. So maybe tcpdump is the only way even to read that log...
 
PMc said:
I've heard that PRI already, just can'r remember. And an IP phone, I would suppose, it's just another broken linux implementation in a closed-shop plastic box?

So, lets use the source: usr.sbin/syslogd/syslogd.c:
Code: 
 * Takes a raw input line, extracts PRI and determines whether the
* message is formatted according to RFC 3164 or RFC 5424. Continues
* parsing of addition fields in the message according to those
* standards and prints the message on the appropriate log files.
*/
static void
parsemsg(const char *from, char *msg)
{
        char *q;
        long n;
        size_t i;
        int pri;

        /* Parse PRI. */
        if (msg[0] != '<' || !isdigit(msg[1])) {
                dprintf("Invalid PRI from %s\n", from);
                return;
        }

So, whatever that IP phone sends, it seems the first char is not a "<" or the second is not a digit.
When doing tcpdump -A, that "PRI" is visible right before the actual message:
................... ........<37>Aug 2 22:11:50 syslogd: last message repeated 1 times
It appears to be a decimal number within <>, encoding one byte, with 32 facilities each having 8 priorities
Click to expand...
Thank you! Yes, it is linux and it is as closed as they make them. SSH login is available, but doesn't avail much: drops you into some kind of shell with 6 commands to choose from :))). You can guess the commands: (1)reconfigure, (2)do NOT reconfigure, (3)do nothing, (4)do nothing and log out, (5)do nothing and save, (6)send a message to your mom...
 
PMc said:
....
So, lets use the source: usr.sbin/syslogd/syslogd.c:
Code: 
 * Takes a raw input line, extracts PRI and determines whether the
* message is formatted according to RFC 3164 or RFC 5424. Continues
* parsing of addition fields in the message according to those
* standards and prints the message on the appropriate log files.
*/
static void
parsemsg(const char *from, char *msg)
{
        char *q;
        long n;
        size_t i;
        int pri;

        /* Parse PRI. */
        if (msg[0] != '<' || !isdigit(msg[1])) {
                dprintf("Invalid PRI from %s\n", from);
                return;
        }
Click to expand...
And you inspirational, too :D! Not that I'm actually going to do what I just thought of (replace these lines with such as would make syslog swallow it for just now :)), but it's always good to have a few options to choose from.

I'll go with tcpdump, to start with.
 
free-and-bsd said:
And you inspirational, too :D! Not that I'm actually going to do what I just thought of (replace these lines with such as would make syslog swallow it for just now :)), but it's always good to have a few options to choose from.
Click to expand...

*laugh* That would be the q&d approach - and such options is one of the main reasons I am using FreeBSD. :)
Obviousely, first of all one should look what is actually happening - it would surprize me if they really break an official RFC-defined protocol.
But then, after it is clear what is wrong, and if there are no other options, a nice&clean approach could be to write a little network filter that would fixup these messages.
 
PMc said:
...
But then, after it is clear what is wrong, and if there are no other options, a nice&clean approach could be to write a little network filter that would fixup these messages.
Click to expand...
Yes, I've just thought about the possibility of creating such filter... The messages I get by tcpdump don't even have what you suggested. This is a typical piece of what I get:
Code: 
myphone.59449 > localhost.syslog: [|syslog]
E..z..@.@..Q.........9...f5.GXP1450_PHONE:[00:0b:82:70:76:09][1.0.8.9] SIPStack::run: Deleting transaction 0:465(REGISTER)
00:24:29.766130 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 140)
    myphone.59449 > localhost.syslog: [|syslog]
E.....@.@..?.........9...x-+GXP1450_PHONE:[00:0b:82:70:76:09][1.0.8.9] ---> Free Transaction in SIPTransaction::release TRANSACTIONID: 00465
00:24:29.819682 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 60, bad cksum 0 (->a89a)!)
So I don't even SEE what would look like PRI.
 
PRI in phone parlance is a trunk line.
So maybe your IP phone is looking for a PRI and not finding it? This maybe a legitimate message from your IP phone
www.linkedin.com

What is a PRI Line, what are the advantages and limitations of PRI circuits

What is a PRI line? - There is only one line physically terminating on the customer PBX but still a PRI line can receive/send 30 calls simultaneously! A PRI line is end to end digital circuit. - A PRI (Primary Rate Interface) line is a form of ISDN (Integrated Services Digital Network) line which is
www.linkedin.com www.linkedin.com
www.atlantech.net

A Guide to SIP Trunking vs PRI: Pros and Cons, Benefits & TCO Breakdown

SIP Trunking vs PRI: What’s the difference, and which is best for your business? First, you need to understand how each choice stacks up, from cost to…
www.atlantech.net
 
Phishfry said:
PRI in phone parlance is a trunk line.
So maybe your IP phone is looking for a PRI and not finding it? This maybe a legitimate message from your IP phone
www.linkedin.com

What is a PRI Line, what are the advantages and limitations of PRI circuits

What is a PRI line? - There is only one line physically terminating on the customer PBX but still a PRI line can receive/send 30 calls simultaneously! A PRI line is end to end digital circuit. - A PRI (Primary Rate Interface) line is a form of ISDN (Integrated Services Digital Network) line which is
www.linkedin.com www.linkedin.com
www.atlantech.net

A Guide to SIP Trunking vs PRI: Pros and Cons, Benefits & TCO Breakdown

SIP Trunking vs PRI: What’s the difference, and which is best for your business? First, you need to understand how each choice stacks up, from cost to…
www.atlantech.net
Click to expand...
No, no, this is taken from a syslog (not the phone's) debug message, about PRI. There was nothing there about the contents of the received messages...
Besides, problems with the phone started just 3 weeks ago, and the provider told me it is because they modified the SIP ID (cut first 6 figures from the beginning).
 
Yes I now see in the syslogd debugging section of the handbook 'pri' output with no real explanation.
Sorry different acronym.
 
free-and-bsd said:
So I don't even SEE what would look like PRI.
Click to expand...

Me neither. It just starts with GXP1450.
So there are a couple of options. Hack the syslogd to accept that and give it some default PRI. Look for a different syslogd implementation that swallows the stuff (there's a couple of them in ports). Or grab the packets and rewrite them - thats a bit of coding effort - and there are various approaches, but I never did that kind of thing, so dunno which would be the easiest way.
 
Thanks! They say a lot of good things about syslog-ng, that it can use filters etc. I'll read more about it... Rewriting the packets sounds funny, but I don't think I have THAT much time for this task :D :D.
 
PMc said:
1. Look for a different syslogd implementation that swallows the stuff (there's a couple of them in ports).
2. Hack the syslogd to accept that and give it some default PRI.
3. Or grab the packets and rewrite them - thats a bit of coding effort
Click to expand...
(I took the liberty to reorder your message).

Option 1 looks like the easiest for someone who is not an experienced programmer. But it will take a few hours, download all those packages, install, configure, and test. And you might not get lucky ... could be there are none that can do it.

Option 2 is the easiest for an experienced programmer: Just go into the source code of the standard syslogd, do a very small patch (if the PRI is invalid or missing, then assign a default value), compile and install. For an inexperienced programmer, this would be playing with fire. Depending on how accurate and careful you want to be, this could be anywhere from half hour to a day of work.

Option 3 is the worst in my humble opinion: Requires programming skill, is hard to test, and creates a complex and fragile system.
 
ralphbsz said:
(I took the liberty to reorder your message).
Click to expand...

You're welcome. It wasn't ordered yet. :)

Option 3 is the worst in my humble opinion: Requires programming skill, is hard to test, and creates a complex and fragile system.
Click to expand...
In my humble opinion it might be the most professional solution. Imagine we have a hotel as customer. 200 of these phones, and a FreeBSD machine to manage them.
We would not want to hack into the base OS, because one might do security updates per binary. We may or may not find a suitable syslogd replacement. But we can write such a filter, probably as a netgraph node to be placed into ipfw. Or something like that. Can be delivered cleanly as a piece of application software, at no change to the standard system.
Imagine we have a dozen hotels as customers, and the boss decides to move system maintenance to India: you would need to write a procedure manual how to reconfigure the syslogd after an upgrade...

(Just scetching some ideas - probably there are other effective solutions)
 
I understand your arguments. It is a difficult tradeoff between having to change a component of the base system, versus adding a whole new moving part. This is why engineering is the art of the compromise.
 
So, as I understand it, it is the app's responsibility to send well-formated output to syslog. And your option is to write another application to do the job on the part of a negligent one... Well, is it not logical to expect some more advanced versions of syslog to do just that?
 
Good question.
First of all, syslog in itself is a kind of liability. It is very old and not well suited to current day demands. It uses an unreliable protocol. It may, under load, damage messages. It does not even provide for the year number in timestamps. There are better solutions, but syslog has become a kind of de-facto standard, and now the IoT hops onto the bandwagon.
Then, the RFC specification is not strict, it does not require the format of the messages, it just suggests it. This was not a problem in the old days, because basically all RFCs are just suggestions for agreements on good engineering practice. And since things do not interoperate without proper agreements, we should be happy to have such suggestions and follow them. But nowadays, if some developer reads "it is RECOMMENDED to transmit a syslog message in the format specified in this document, but it is not required. (RFC3164)", he thinks, okay then I can leave that out and spare some time.

If there are two pieces that do not interoperate, and if the one that behaves bad cannot be fixed, my favourite approach is usually to add a third piece in between to adjust things. This may appear to add complexity, but I think it rather helps to maintain manageability: if I change a given thing (and in this case, a rather big thing, like an OS), the change is not obvious, it is usually not visible to another person; it usually needs documentation and it needs somebody to actually find and read that documentation. Whereas a separate component explains itself already by it's sheer existance: it must be needed for something, otherwise it weren't there. (This adheres to the old unix philosophy of building a system not monolithic, but out of small pieces that do small things.) And it can simply be dropped when no longer needed.

Finally, yes, You are right, another option could be to create a change request in the FreeBSD to add another option to syslogd so that it may suppress the check for the PRI field.
 
Well, I don't know prog. languages other than BASH scripting, but I imagine, inserting a missing word into a string the program is working with anyway can't be too much trouble... even interesting. That could get one deeper into C language... funny to an extent.
 
free-and-bsd said:
So, as I understand it, it is the app's responsibility to send well-formated output to syslog. And your option is to write another application to do the job on the part of a negligent one... Well, is it not logical to expect some more advanced versions of syslog to do just that?
Click to expand...
I just looked up the current RFC for syslog (it's RFC 5424 from 2009). It is very clear about the header format, and it says that the header must begin with the PRI field, which must be in the format "<123>", with angle brackets around it, and 1 to 3 digits. On the other hand, it is quite possible that your IP phones are older than 2009, and the previous version of the RFC was more tolerant. And in reality, all RFCs are optional, since the only punishment for non-compliance is lack of interoperability.

Which brings me to the real question. Your IP phones send syslog messages for some useful purpose. Whoever implemented them didn't waste the time of writing the syslog sending code just for fun, they had a reason for it. Similarly, you are trying to collect them for another useful purpose (same argument, you wouldn't be wasting your time if it had no value). So the syslog implementation of the IP phone must have worked at some point in the past. My bet is that the phones are part of a larger system, which includes a server of some sort. And that server probably has a working syslog implementation that functions correctly with the phones. Maybe you could do some searching and find out more about that server? Maybe the server consists of source code, perhaps including a specialized syslogd implementation, which you could just port to FreeBSD?

Now, in the meantime, I think the FreeBSD syslog implementation is defective. It violates what's called "Postel's law", and the "principle of least surprise". Jon Postel is considered *the* father of the internet, and his law says: Be conservative in what you send, be liberal in what you accept. The syslog implementation should not throw away an incoming message that can be mostly parsed, just because the PRI field is missing or formatted wrong. It could instead take a sensible guess at severity and facility (for example "notice" and "local7"), and construct a default PRI, or it could arrange for the rest of the flow to function without PRI. And it violates the principle of least surprise by doing something surprising (removing an incoming message) and not telling anyone about it; instead it could log a message, for example by saying "syslog received a message from host 12.34.56.78 port 9876 that was not parseable, and had to be discarded". If someone had some spare time and wanted to do something good for FreeBSD, they could open a PR, and prepare a patch for the syslogd source code that makes it behave better.
 
free-and-bsd said:
Well, I don't know prog. languages other than BASH scripting, but I imagine, inserting a missing word into a string the program is working with anyway can't be too much trouble... even interesting. That could get one deeper into C language... funny to an extent.
Click to expand...

Thats what I was thinking: if You or somebody would be interested, it could be a nice task to get some experiece in handling network stuff. But it's already a bit of an advanced task: fixing the string itself is simple, yes, but that happens within a network packet, so we must fetch this packet out of the network, read and process it properly (there is a network header), and afterwards reassemble a valid packet (checksums etc.) and reinsert it into the network. Certainly there are tools and libraries for all that, so it is an interesting task for somebody who has managed the basic way of C programming and is looking for more advanced things.

ralphbsz said:
Which brings me to the real question. Your IP phones send syslog messages for some useful purpose. Whoever implemented them didn't waste the time of writing the syslog sending code just for fun, they had a reason for it. Similarly, you are trying to collect them for another useful purpose (same argument, you wouldn't be wasting your time if it had no value). So the syslog implementation of the IP phone must have worked at some point in the past. My bet is that the phones are part of a larger system, which includes a server of some sort. And that server probably has a working syslog implementation that functions correctly with the phones.
Click to expand...

Exactly. At least they must have used some kind of system for their testing.
Probably we could shorten this and just ask: what kind of syslog does Linux use?

But, if we ask that, we don't get an answer - instead we get the full beauty of the Linux "bazaar": some sources say, Linux uses a port from BSD syslog, some sources say it uses journald, some say it uses syslog-ng. Most likely all of this is true. :(

So, as now I was already curious, I gave it a bet and unpacked the syslog-ng.
And after searching around for some while, I found this: sysutils/syslog-ng/work/syslog-ng-3.21.1/modules/syslogformat/syslog-format.c:
Code: 
static gboolean
log_msg_parse_pri(LogMessage *self, const guchar **data, gint *length, guint flags, guint16 default_pri)
{
  [... variable declaration stuff ...]

  if (left && src[0] == '<')
    {
      [ ... parsing stuff ... ]
    }
  /* No priority info in the buffer? Just assign a default. */
  else
    {
      self->pri = default_pri != 0xFFFF ? default_pri : (EVT_FAC_USER | EVT_PRI_NOTICE);
    }

  *data = src;
  *length = left;
  return success;
}

So that answers all questions.

Now, in the meantime, I think the FreeBSD syslog implementation is defective. It violates what's called "Postel's law", and the "principle of least surprise". Jon Postel is considered *the* father of the internet, and his law says: Be conservative in what you send, be liberal in what you accept. The syslog implementation should not throw away an incoming message that can be mostly parsed, just because the PRI field is missing or formatted wrong. It could instead take a sensible guess at severity and facility (for example "notice" and "local7"), and construct a default PRI, or it could arrange for the rest of the flow to function without PRI. And it violates the principle of least surprise by doing something surprising (removing an incoming message) and not telling anyone about it; instead it could log a message, for example by saying "syslog received a message from host 12.34.56.78 port 9876 that was not parseable, and had to be discarded". If someone had some spare time and wanted to do something good for FreeBSD, they could open a PR, and prepare a patch for the syslogd source code that makes it behave better.
Click to expand...

I agree. This sounds substantial enough for a change request, albeit I fear the answer might be, use syslog-ng.
Interim I checked my phone, and the pointy hat seems to have slightly passed me for now - that's an Alcatel, and it sends priorities...
 
Okay. I can't test it, but that might be it:

Code: 
Index: syslogd.c
===================================================================
--- syslogd.c   (revision 350322)
+++ syslogd.c   (working copy)
@@ -1259,30 +1259,32 @@
        /* Parse PRI. */
        if (msg[0] != '<' || !isdigit(msg[1])) {
                dprintf("Invalid PRI from %s\n", from);
-               return;
+               pri = DEFUPRI;
+       } else {
+               for (i = 2; i <= 4; i++) {
+                       if (msg[i] == '>')
+                               break;
+                       if (!isdigit(msg[i])) {
+                               dprintf("Invalid PRI header from %s\n", from);
+                               return;
+                       }
+               }
+               if (msg[i] != '>') {
+                       dprintf("Invalid PRI header from %s\n", from);
+                       return;
+               }
+               errno = 0;
+               n = strtol(msg + 1, &q, 10);
+               if (errno != 0 || *q != msg[i] || n < 0 || n >= INT_MAX) {
+                       dprintf("Invalid PRI %ld from %s: %s\n",
+                           n, from, strerror(errno));
+                       return;
+               }
+               pri = n;
+               if (pri &~ (LOG_FACMASK|LOG_PRIMASK))
+                       pri = DEFUPRI;
+               msg += i + 1;
        }
-       for (i = 2; i <= 4; i++) {
-               if (msg[i] == '>')
-                       break;
-               if (!isdigit(msg[i])) {
-                       dprintf("Invalid PRI header from %s\n", from);
-                       return;
-               }
-       }
-       if (msg[i] != '>') {
-               dprintf("Invalid PRI header from %s\n", from);
-               return;
-       }
-       errno = 0;
-       n = strtol(msg + 1, &q, 10);
-       if (errno != 0 || *q != msg[i] || n < 0 || n >= INT_MAX) {
-               dprintf("Invalid PRI %ld from %s: %s\n",
-                   n, from, strerror(errno));
-               return;
-       }
-       pri = n;
-       if (pri &~ (LOG_FACMASK|LOG_PRIMASK))
-               pri = DEFUPRI;
 
        /*
         * Don't allow users to log kernel messages.
@@ -1293,7 +1295,6 @@
                pri = LOG_MAKEPRI(LOG_USER, LOG_PRI(pri));
 
        /* Parse VERSION. */
-       msg += i + 1;
        if (msg[0] == '1' && msg[1] == ' ')
                parsemsg_rfc5424(from, pri, msg + 2);
        else
 
While you were doing useful coding, I was hauling 75 lbs heavy concrete blocks, and wheelbarrows full of dirt, and building a retaining wall in the garden. I think your project for the day was more useful.
 
You must log in or register to reply here.
Back
Top