Fixed Error logging fails if method contains invalid string argument

[digitalpoint]

Affected version

2.2

I won't dive too deep into the "why", but it's third-party classes that are out of my control (some WebSocket stuff). I noticed that when I explicitly tried to log an error message like so:

\XF::logError('some error', true);

...it wouldn't get logged.

Did some debugging and it turns out it was a MySQL error that was causing it on the trace_string column: MySQL query error [1366]: Incorrect string value: '\x81\x895\x81\x84\x89...' for column 'trace_string' at row 1#0 src/XF.php(213)...

Dumped the XF generated trace_string to see what was going on:

#1 src/addons/DigitalPoint/Messaging/Service/WebSocket/Pusher.php(39): XF::logError('WebSocket metho...', true)
#2 src/addons/DigitalPoint/Messaging/vendor/cboden/ratchet/src/Ratchet/WebSocket/WsServer.php(75): DigitalPoint\Messaging\Service\WebSocket\Pusher->onMessage(Object(Ratchet\WebSocket\WsConnection), Array)
#3 src/addons/DigitalPoint/Messaging/vendor/cboden/ratchet/src/Ratchet/WebSocket/WsServer.php(131): Ratchet\WebSocket\WsServer->Ratchet\WebSocket\{closure}(Object(Ratchet\WebSocket\WsConnection), Object(Ratchet\RFC6455\Messaging\Message))
#4 src/addons/DigitalPoint/Messaging/vendor/ratchet/rfc6455/src/Messaging/MessageBuffer.php(248): Ratchet\WebSocket\WsServer->Ratchet\WebSocket\{closure}(Object(Ratchet\RFC6455\Messaging\Message), Object(Ratchet\RFC6455\Messaging\MessageBuffer))
#5 src/addons/DigitalPoint/Messaging/vendor/ratchet/rfc6455/src/Messaging/MessageBuffer.php(194): Ratchet\RFC6455\Messaging\MessageBuffer->processData('??5???]???Z???')
#6 src/addons/DigitalPoint/Messaging/vendor/cboden/ratchet/src/Ratchet/WebSocket/WsServer.php(153): Ratchet\RFC6455\Messaging\MessageBuffer->onData('??5???]???Z???')
#7 src/addons/DigitalPoint/Messaging/vendor/cboden/ratchet/src/Ratchet/Http/HttpServer.php(54): Ratchet\WebSocket\WsServer->onMessage(Object(Ratchet\Server\IoConnection), '??5???]???Z???')
#8 src/addons/DigitalPoint/Messaging/vendor/cboden/ratchet/src/Ratchet/Server/IoServer.php(112): Ratchet\Http\HttpServer->onMessage(Object(Ratchet\Server\IoConnection), '??5???]???Z???')
#9 src/addons/DigitalPoint/Messaging/vendor/cboden/ratchet/src/Ratchet/Server/IoServer.php(95): Ratchet\Server\IoServer->handleData('??5???]???Z???', Object(React\Socket\Connection))
#10 src/addons/DigitalPoint/Messaging/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php(123): Ratchet\Server\IoServer->Ratchet\Server\{closure}('??5???]???Z???')
#11 src/addons/DigitalPoint/Messaging/vendor/react/stream/src/Util.php(71): Evenement\EventEmitter->emit('data', Array)
#12 src/addons/DigitalPoint/Messaging/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php(123): React\Stream\Util::React\Stream\{closure}('??5???]???Z???')
#13 src/addons/DigitalPoint/Messaging/vendor/react/stream/src/DuplexResourceStream.php(196): Evenement\EventEmitter->emit('data', Array)
#14 src/addons/DigitalPoint/Messaging/vendor/react/event-loop/src/StreamSelectLoop.php(245): React\Stream\DuplexResourceStream->handleData(Resource id #138)
#15 src/addons/DigitalPoint/Messaging/vendor/react/event-loop/src/StreamSelectLoop.php(212): React\EventLoop\StreamSelectLoop->waitForStreamActivity(NULL)
#16 src/addons/DigitalPoint/Messaging/Cli/WebSocketServer.php(80): React\EventLoop\StreamSelectLoop->run()
#17 {main}

Don't know why it's passing around invalid strings as args, but it is... which is making error logging fail.

In XF\Error, I changed this:

$args[] = "'$tmp'";

to this:

if (preg_match("//u", $tmp))
{
   $args[] = "'$tmp'";
}
else
{
   $args[] = "[invalid]";
}

Might be a worthwhile change (only log the method arguments in the trace if they are valid utf8). Would rather get some error in the error log vs. getting nothing at all because MySQL can't take it. I can't imagine a scenario where XF is trying to log a server error, but we would like it to fail because something had invalid strings as parameters somewhere in the chain.

 

[digitalpoint]

Not sure why I didn't think of this before... but it's just binary data and PHP's gettype() function doesn't recognize binary because PHP doesn't have a specific binary type. So ya... if a method is passing in binary data as an argument, it's not going to be able to be inserted into a utf8-specific column.

 

[digitalpoint]

Not so coincidentally, other errors started popping up in my XF server error log once I applied that change to \XF\Error...

• ErrorException: [E_NOTICE] fwrite(): send of 41 bytes failed with errno=32 Broken pipe

Turns out there's some special sauce that needs to be done when dealing with utf-8 characters with fwrite() (been failing silently for years and never knew about it since writing of the error log itself was failing): https://stackoverflow.com/questions/6336586/fwrite-and-utf8

 

[PaulB]

Turns out there's some special sauce that needs to be done when dealing with utf-8 characters with fwrite() (been failing silently for years and never knew about it since writing of the error log itself was failing): https://stackoverflow.com/questions/6336586/fwrite-and-utf8

That shouldn't be necessary. fwrite handles raw byte streams and doesn't care about encoding. The Stack Overflow question to which you linked has several issues and misconceptions, none of which have anything to do with fwrite.

If you have valid UTF-8, you should be able to write it out with fwrite and get a valid file. If you have invalid UTF-8, you'll get an invalid file. If you try to do funky detection and conversions with mb_* like the author of that SO question, you're probably going to end up in the latter scenario.

In either case, it shouldn't fail; it should just output the raw data.

 

[digitalpoint]

Sorry, I wasn't clear... In this case, fwrite() is writing binary data, not a properly encoded utf8 string. The failure doesn't get logged to the XF server error log because a non-utf8 string was passed as an argument.

The underlying issue is that the \XF\Error class is trying to log arguments from the backtrace to a MySQL column that is utf8. So if you work with binary things (images, WebSockets, etc.) those errors will fail silently because the MySQL insert fails.

 

[XF Bug Bot]

Thank you for reporting this issue, it has now been resolved. We are aiming to include any changes that have been made in a future XF release (2.2.12).

Change log:

Ensure error logging isn't silently skipped if stacktrace arguments contain invalid utf-8.

There may be a delay before changes are rolled out to the XenForo Community.