Syslog module's serialization of log components possibly broken

Hi Goba,

I think this is a great idea and looks to me like the best of the solutions.

About the patch, just an idea: we could keep function arguments as they are now, but having either an string or an array for the second one. The watchdog funcion could look which type is passed and then log the message, or the message plus arguments depending on that.

This way it would be backwards compatible -which I know is not the main goal- but it will also simplify the function call when no arguments are needed. It would look like:

watchdog('user', array('External load by %user using module %module.', '%user' => ..., '%module' =>..., )

A simple array shifting will do to separate the main string from arguments array...

Since this changes watchdog()'s arguments, it can't be done in 5.0.

There is a fly in the ointment: dblog (nee watchdog) is not the only mechanism that uses the watchdog hook. Other modules now use that hook to route messages, even outside of Drupal (e.g. email, syslog).

For these, there is no way for applying a delayed t().

So, while your solution will address the dblog part, it will leave an unaddressed area for the rest of the module.

Don't know offhand what the best solution would be.

Gabor

The severity column needs to be moved after the uid column for performance reasons.

See also #40657.

If I understand correctly, Gabor's proposal would result in the watchdog hook always calling consumers with English messages, and dblog would then store that data in his modified format, allowing translation at viewing time. If that's essentially correct, then I agree.

Alternatively, there could be an admin selected language to which all messages are translated before passing to consumers. That would allow an admin to choose to have all watchdog messages in Spanish (for example), whether stored in the Drupal dblog database table, or issued to syslog or sent via SMS. I'm not sure what kind of technical effort that might require. it might be simple, or not.

Oh, I thought this had been committed time ago :-(

Anyway, I think Gabor's patch is great, and not only a good solution for the problem, but 'the good one'.

So I think we should go ahead with it and let's leave all the other performance fixes for a different patch. Sure there are many other issues we can fix, but one step at a time...

subscribing via http://drupal.org/node/40657 (which was marked as duplicate of this)

Gabor

Few comments:

1. We need an update_2008() in system.install so the watchdog table schema is upgraded with the new column.

2. The severity column needs to move after type and before the other text fields for the sake of performance.

3. We can change the watchdog() function signature to make the $variables parameter optional. This leaves only the first two parameters as required ($type and $message). This way modules/sites that don't use care about language can just send their message in and have it be AS IS.

So:

function watchdog($type, $message, $severity = WATCHDOG_NOTICE, $variables = array(), $link = NULL)

Also, why don't we take the plunge and just make the argument a keyed array. Every other part of Drupal is moving in that direction, so why not consider it for this too?

4. I also do not understand why we have + before and after in this patch:

RCS file: /cvs/drupal/drupal/modules/dblog/dblog.install,v
retrieving revision 1.1
diff -u -p -r1.1 dblog.install
--- modules/dblog/dblog.install	10 Apr 2007 10:10:27 -0000	1.1
+++ modules/dblog/dblog.install	12 Apr 2007 14:57:53 -0000
@@ -13,6 +13,7 @@ function dblog_install() {
         uid int NOT NULL default '0',
         type varchar(16) NOT NULL default '',
         message longtext NOT NULL,
+        variables longtext NOT NULL,
         severity tinyint unsigned NOT NULL default '0',
         link varchar(255) NOT NULL default '',
         location text NOT NULL,
@@ -30,6 +31,7 @@ function dblog_install() {
         uid int NOT NULL default '0',
         type varchar(16) NOT NULL default '',
         message text NOT NULL,
+        variables text NOT NULL,
         severity smallint_unsigned NOT NULL default '0',
         link varchar(255) NOT NULL default '',
         location text NOT NULL default '',

I will test it after you address the above.

I'm in support for this patch.

I think the benefit of this patch outweight the drawback (not being able to sort messages). I think this drawback can be overcome by implementing a vastly superior filtering system for the watchdog table. Also, if watchdog tables can't be sorted correctly, it probably makes sense not to make them sortable.

Should we document in the PHPdoc API why we are taking the arguments separately?

I'd like to see this patch committed, but it is probably worth thinking it through a bit more. What is going to be the impact on a filter mechanism? Things might become non-trivial.

See http://drupal.org/node/67893 for the filter discussion. It would be good to keep that issue in mind when developing this patch.

Great patch, I just tested on a recent HEAD and it works fine.

Committed to CVS HEAD.

I'm marking this 'code needs work' until the upgrade documentation has been updated.

Feel free to mark this fixed once the handbook is up-to-date.

Thanks Gabor!

Few localization-unfriendly watchdogs ;-)

Gabor,

Do we really need the third parameter if we are not translating, or if there are no tokens?

I mean can't we just do:

watchdog('user', 'User has logged in');

Or do we have to specify a NULL or array() on every call?

It would be better to default the third parameter and not force everyone to pass something, even if it is an empty array or a NULL.

Gabor

The only reason syslog used t() was that this is a theme function for token substitution, not really a language translation.

The t() can be removed.

Gabor

Re: your first point,

My comment was for the documentation here http://drupal.org/node/114774#watchdog_parameters

Specifically this part;

If you have a message which has no placeholders to replace with values, pass on an empty array(). If you have a dynamically generated message (a PHP error message, a message coming from a remote service or some other type of message, whose literal text cannot be included in the second parameter), please pass on NULL in place of the variables parameter, so Drupal knows that the message is not for translation.

And the examples:

// Translatable message, but no placeholders to replace
watchdog('soap', 'Soap message sent.', array());
// Not translatable message
watchdog('soap', $remote_soap_message, NULL);

Can we see the most used case and default the 3rd parameter to it (whether NULL or array()), so we don't have to pass it in every call?

Am I being clear?

Re: your second point for syslog theme function, the @ was used to strip out all HTML markup, since it is very unsightly (makes my eyes bleed) in syslog.

What I can do is clean up that function and use strip_tags() everywhere instead and remove all references to t(). How about that?

Goba

Re: syslog.

How about something like this? (not sure about the last segment about $message and $variables, need your input on that part).

Remember that we just need a decent default, not perfect nor all encompassing, since this function is themable and people can override it anyway they like.

function theme_syslog_format($entry) {
  global $base_url;

  $message  = $base_url;
  $message .= '|' . $entry['timestamp'];
  $message .= '|' . $entry['type'];
  $message .= '|' . $entry['ip'];
  $message .= '|' . $entry['request_uri'];
  $message .= '|' . $entry['referer'];
  $message .= '|' . $entry['user']->uid;
  $message .= '|' . strip_tags($entry['link']);
  $message .= '|' . strip_tags(is_null($entry['variables']) ? $entry['message'] : strtr($entry['message'], $entry['variables'])),

  return $message;
}

I meant to say that I am not sure about the last line which contains "$entry['message'] and $entry['variables']" not $message and $variables.

syslog output can be displayed, processed and converted with a variety of tools. Syslog messages are often shown in broswer windows and have to be sanitized. See http://216.147.18.102/ams/ , http://www.dangermen.com/smt/screens.html, http://www.phpwizardry.com/php-syslog-ng.php or http://www.googlog.org/.

This replaces t() with strtr(). It could be as well use implode() actually, but I feel strtr() is easier to read/customize.

And adds/uses _syslog_strip_html_tags() as a safe alternative for strip_tags().

I'm not saying we should escape the strings. I'm just saying that they could be used unescaped because I don't think syslog expect to see HTML code. Not sure what to do with it, but it seems best to send non-HTML text to syslog.

syslog can be used in many different ways. The most common case is just to tail the log, or use less or similar to view it. Viewing it in a browser is not the only way (and I should say not the most common way either, having worked with monitoring systems before).

So, any markup in it (HTML or otherwise) will be distracting. Plain text is the most common way to view/process syslog.

Again, this is a themable function. We just provide a reasonable default. It can be overridden by anyone who does not like the way we process the text by a simple function in template.php or other means.

Alienbrain's patch is a step in the right direction. For the sake of consistency, @link should be treated the same as @message. The part I do not like about it is the _syslog_strip_html_tags(). Although it does the job in this case, it should be a generic function not specific to this module. Perhaps making it strip_html_tags() in one of the includes would be best?

I agree with kbahey: (1) let's strip the HTML and (2) the provided HTML stripper is not particularly elegant. Can't we use the built-in PHP functionality or something that is a bit more future proof?

Here is a new patch.

It strips the HTML, and eliminates the t() altogether so we are in sync with Goba's previous patch.

it also fixes the few cases in core where we have the email enclosed in angled brackets, so that info does not get lost.

Except for the comma that needs to be a semicolon, that causes a PHP syntax error!

Bad Khalid, no biscuit ...

Here is a fixed version.

Just edited the patch to conform to code style. '|' . became '|'.

I've searched conrib and here is a list of modules that has tags which are not HTML in any of their watchdog messages, if this patch goes in, I will make sure to submit issues for them to change the syntax of their affected watchdog messages:

• advuser
• email
• feedback
• gojoingo
• logintoboggan
• user_import
• welcome

Personally, I find the use of square brackets strange. The rest of the world use less than and greater than signs for e-mail address. This might even be a standard. Round brackets are better than square brackets, IMO.

Also, why don't we move those brackets in the string itself?

Rerolled with parens as per Dries.

Committed to CVS HEAD. Thanks! :)

This is not "to be ported" in the usual sense.

Rather, it is a reminder for alienbrain to open the appropriate issues for the modules mentioned in #46 above.

You may want to explicitly mention parenthesis instead of angled brackets.

Please mark as fixed after this is done.

The tag stripping does not make sense. Either syslog information is plain text, or it is HTML. In the latter case, we don't need to do anything. In the former case, we need to remove all tags and convert the rest to plain text.

This patch only removes tags, but doesn't actually convert to plain text. Needs work.

Why on earth is it so hard to get this right people?

I think what Steven is talking about is that previously strings was being passed with the '@' placeholder, which causes t() to format them using check_plain(). Also we currently don't strip out '|' characters, which could cause watchdog to break with messages containing this character.

How about this simple patch that replaces strip_tags with check_plain?

If you want it as an attachement, let me know.

Index: modules/syslog/syslog.module
===================================================================
RCS file: /cvs/drupal/drupal/modules/syslog/syslog.module,v
retrieving revision 1.9
diff -u -F^f -r1.9 syslog.module
--- modules/syslog/syslog.module        4 Jul 2007 21:35:24 -0000       1.9
+++ modules/syslog/syslog.module        2 Oct 2007 17:35:37 -0000
@@ -95,8 +95,8 @@ function theme_syslog_format($entry) {
   $message .= '|'. $entry['request_uri'];
   $message .= '|'. $entry['referer'];
   $message .= '|'. $entry['user']->uid;
-  $message .= '|'. strip_tags($entry['link']);
-  $message .= '|'. strip_tags(is_null($entry['variables']) ? $entry['message'] : strtr($entry['message'], $entry['variables']));
+  $message .= '|'. check_plain($entry['link']);
+  $message .= '|'. check_plain(is_null($entry['variables']) ? $entry['message'] : strtr($entry['message'], $entry['variables']));

   return $message;
 }

Even if it is late again in the release cycle, this time this bug must be fixed.

We are having an incredibly powerful new translation system in D6. Therefore D6 will be used a lot for multilingual sites. Imagine an administrator at the EU or U.N. How useful is for him a log with Basque, Estonian and Greek entries intermixed?

For this reason this bug is rather critical than normal IMHO.

And yes, I set this to critical, because it does break functionality, namely the watchdog/syslog, for multilingual sites.

@Gábor: I'm sorry, you're absolutely right. Maybe I'm being too bold today... I'm gonna take some days break :)
I just stumbled upon this issue, and was surprised that would be still not fixed. Sorry again...

Patch attached. It provides the following improvements:

• Message entities are decoded. That should address #51.
• The | (pipe) is indeed not the best separator as it can exist in URLs. Every field is now double-quoted and a single whitespace is used as a separator. (more on why this was chosen below). That should address #57
• Another new issue is that currently the $link parameter is passed as is after stripping its tags, so the link <a href="http://example.com/user/123">View user profile</a> will end up as plain text <code>View user profile in the syslog entry. The patch converts such links to View user profile: http://example.com/user/123.

On why a white space with double quoting as the separator, we needed something which can't exist in our values. We can discard the message as it comes last. That leaves mainly the URIs. URIs cannot have double quotes nor whitespaces, i.e. they are always encoded. Unfortunately the watchdog $type can contain whitespaces so we can't use them alone for separating, also, whitespaces can make it difficult to notice when a field has an empty value (i.e. when you are reading the line, there is no indicator that there is a field here with an empty value). Thus, we double-quote values and separate with a whitespace. There were other options, like > which can be used and is pretty safe, however is very bad readability wise. Syslogs are often read as is, not necessarily parsed.

As an example of the final output, the following URI:

http://pipeline/~alienbrain/drupal/?q=gimme some 404s&foo="@$bar"

Produces the following syslog entry:

Apr 18 21:06:16 pipeline drupal: "http://pipeline/~alienbrain/drupal" "1240081576" "page not found" "127.0.0.1" "http://pipeline/~alienbrain/drupal/?q=gimme%20some%20404s&foo=%22@$bar%22" "" "1" "" gimme some 404s

Looks good overall, except I am -1 on using space as a delimiter. The reason is that this does not lend itself to command line tools, e.g. awk ...etc. when you are looking for things in the syslog.

For example, to get a quick count of each type of errors I do:

awk -F'|' '{data[$3]++ } END {for (i in data) print data[i], i}' $SYSLOG | sort -n

Space would not allow these things. I can settle for semicolon or anything that is less likely to be in the strings of the messages.

The double-quoted whitespace-separated format is certainly slightly harder to digest from cli, but really, if we want to get this right then this is it. (Or we could use > but that looks horrible when read :)

Did you know that replacing -F'|' with -F'"(^"|" "|"$)' does the trick for the (rather nifty) command you showed? (You have to use $4 instead of $3 though, because with that field separate $1 will always be empty, so the first field is $2, the second is $3, and so on)

... and for PHP CLI: echo '"field one" "field two" "field three"' | php -r '$l=fgetcsv(STDIN, 1000, " "); var_dump($l);' prints:

array(3) {
  [0]=>
  string(9) "field one"
  [1]=>
  string(9) "field two"
  [2]=>
  string(11) "field three"
}

I guess since this is a theme function, I can override it and use | as a delimited.

But it is still too cryptic as a default implementation (me thinks).

#62: syslog_plaintext-76588.patch queued for re-testing.