Last Updater: Processing: MailBodies Error

[zantharax]

Problem Statement

After running API update for certain characters, an error is generated - "Last Updater: Processing: MailBodies"

Log Extracts / Proof

Last Updater: Processing: MailBodies

Exception: Pheal\Exceptions\PhealException
Error Code: 0
Error Message: Original exception: String could not be parsed as XML
File: /var/www/seat/vendor/3rdpartyeve/phealng/lib/Pheal/Pheal.php - Line: 289

Traceback: #0 /var/www/seat/vendor/3rdpartyeve/phealng/lib/Pheal/Pheal.php(110): Pheal\Pheal->requestXml('char', 'MailBodies', Array)
#1 /var/www/seat/vendor/eveseat/eveapi/src/Api/Character/MailBodies.php(69): Pheal\Pheal->__call('MailBodies', Array)
#2 /var/www/seat/vendor/eveseat/eveapi/src/Api/Character/MailBodies.php(69): Pheal\Pheal->MailBodies(Array)
#3 /var/www/seat/vendor/eveseat/eveapi/src/Jobs/UpdateAuthenticated.php(99): Seat\Eveapi\Api\Character\MailBodies->call()
#4 [internal function]: Seat\Eveapi\Jobs\UpdateAuthenticated->handle()
#5 /var/www/seat/bootstrap/cache/compiled.php(1187): call_user_func_array(Array, Array)
#6 /var/www/seat/bootstrap/cache/compiled.php(9441): Illuminate\Container\Container->call(Array)
#7 [internal function]: Illuminate\Bus\Dispatcher->Illuminate\Bus\{closure}(Object(Seat\Eveapi\Jobs\UpdateAuthenticated))
#8 /var/www/seat/bootstrap/cache/compiled.php(9593): call_user_func(Object(Closure), Object(Seat\Eveapi\Jobs\UpdateAuthenticated))
#9 [internal function]: Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Seat\Eveapi\Jobs\UpdateAuthenticated))
#10 /var/www/seat/bootstrap/cache/compiled.php(9575): call_user_func(Object(Closure), Object(Seat\Eveapi\Jobs\UpdateAuthenticated))
#11 /var/www/seat/bootstrap/cache/compiled.php(9448): Illuminate\Pipeline\Pipeline->then(Object(Closure))
#12 /var/www/seat/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(43): Illuminate\Bus\Dispatcher->dispatchNow(Object(Seat\Eveapi\Jobs\UpdateAuthenticated), Object(Closure))
#13 /var/www/seat/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(129): Illuminate\Queue\CallQueuedHandler->call(Object(Illuminate\Queue\Jobs\RedisJob), Array)
#14 /var/www/seat/vendor/laravel/framework/src/Illuminate/Queue/Jobs/RedisJob.php(50): Illuminate\Queue\Jobs\Job->resolveAndFire(Array)
#15 /var/www/seat/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(208): Illuminate\Queue\Jobs\RedisJob->fire()
#16 /var/www/seat/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(159): Illuminate\Queue\Worker->process('redis', Object(Illuminate\Queue\Jobs\RedisJob), '10', '0')
#17 /var/www/seat/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(109): Illuminate\Queue\Worker->pop('', 'high,medium,low...', '0', '3', '10')
#18 /var/www/seat/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(71): Illuminate\Queue\Console\WorkCommand->runWorker('', 'high,medium,low...', '0', '128', false)
#19 [internal function]: Illuminate\Queue\Console\WorkCommand->fire()
#20 /var/www/seat/bootstrap/cache/compiled.php(1187): call_user_func_array(Array, Array)
#21 /var/www/seat/vendor/laravel/framework/src/Illuminate/Console/Command.php(150): Illuminate\Container\Container->call(Array)
#22 /var/www/seat/vendor/symfony/console/Command/Command.php(256): Illuminate\Console\Command->execute(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#23 /var/www/seat/vendor/laravel/framework/src/Illuminate/Console/Command.php(136): Symfony\Component\Console\Command\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#24 /var/www/seat/vendor/symfony/console/Application.php(841): Illuminate\Console\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#25 /var/www/seat/vendor/symfony/console/Application.php(189): Symfony\Component\Console\Application->doRunCommand(Object(Illuminate\Queue\Console\WorkCommand), Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#26 /var/www/seat/vendor/symfony/console/Application.php(120): Symfony\Component\Console\Application->doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#27 /var/www/seat/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(107): Symfony\Component\Console\Application->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#28 /var/www/seat/artisan(36): Illuminate\Foundation\Console\Kernel->handle(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#29 {main}

Output of php artisan seat:admin:diagnose

SeAT Diagnostics
If you are not already doing so, it is recommended that you run this as the user the workers are running as.
Eg:
    sudo -u apache php artisan seat:admin:diagnose
This helps to check whether the permissions are correct.

 * Getting environment information
Current User: www-data
PHP Version: 5.6.18-1+deb.sury.org~trusty+1
Host OS: Linux novos-coms-svr-00 3.19.0-49-generic #55~14.04.1-Ubuntu SMP Fri Jan 22 11:24:31 UTC 2016 x86_64
SeAT Basepath: /var/www/seat

 * Checking DEBUG mode
Debug mode disabled

 * Checking storage
/var/www/seat/storage is writable
/var/www/seat/storage/app/pheal/ is writable
/var/www/seat/storage/sde/ is writable
/var/www/seat/storage/logs/laravel.log is writable

 * Checking Database
+------------+----------------------------------+
| Setting    | Value                            |
+------------+----------------------------------+
| Connection |                                  |
| Host       | localhost                        |
| Database   | seat                             |
| Username   | seat                             |
| Password   | ******************************** |
+------------+----------------------------------+
Connection OK to database: seat

 * Checking Redis
+----------+-----------+
| Setting  | Value     |
+----------+-----------+
| Host     | 127.0.0.1 |
| Port     | 6379      |
| Database | 0         |
+----------+-----------+
Connected to Redis
Set random key of: z0T0STR5GBy0AJKoRqCbOqPKb8pPovxR9d0Cnwy1hcuwGADsmXc3JJpQ2pUlu7qu
Set key to expire in 10 sec
Read key OK

 * Checking Pheal EVE API Access
Server Online: True
Online Players: 32142

Checking Local and Github Versions. Please wait...
+---------------+---------------+---------------+
| Package Name  | Local Version | Latest Github |
+---------------+---------------+---------------+
| Api           | 1.0.9         | 1.0.9         |
| Console       | 1.0.10        | 1.0.10        |
| Eveapi        | 1.0.11        | 1.0.11        |
| Notifications | 1.0.4         | 1.0.4         |
| Web           | 1.0.22        | 1.0.22        |
| Services      | 1.0.14        | 1.0.14        |
+---------------+---------------+---------------+
SeAT Diagnostics complete

[leonjza]

Could it be that you had some connectivity problems at some stage? This error indicates that the XML we got from CCP was corrupt/invalid/empty.

[zantharax]

No, I doubt so. These are the only errors that occur and they trigger very predictably. This happens on 13 specific keys, every time I run them. Could it be something in a mail that these 13 accounts have that is causing issues when parsing the API pull?

[leonjza]

If it is that predictable, could you have a look at the XML that is on disk and reply with it here?

[zantharax]

Sorry, I'm not sure how to go about that. I've tried to go through the mailboxes stored for a pair of these keys, and compare it to a key that is not generating this error, but cannot find any mails unique to these keys that could contain the error.

If you have anywhere else to look, or a better way to identify where the problem may be I would be more than happy to do so.

[freedenizen]

If you look in /var/www/seat/app/storage/cache/phealcache/KEYID/VCODE/char you should see directories for the various things pulled by that key, and in those directories xml files.

[zantharax]

The directory is slightly different than what you described - /var/www/seat/storage/app/pheal/(KEYID)/(VCODE)/ However, the /char/MailBodies/ directory is empty of any files.

Looking at known-good keys, this directory appears to be removed (perhaps this is done after mails are parsed). I've have tried clearing the cache, and specifically removed the /Mailbodies directory, but it is recreated on the API Query run. Permissions look good as well, 777 to www-data (the user seat is running as).

[freedenizen]

Sorry I gave you the path for 0.x not 1.x

[zantharax]

No worries, was able to poke around and find it.

[zantharax]

After doing some more comparison, I was able to find the offending mail. In other API clients, I receive a Malformed XML error as well. I would suspect that the mail (which is bi-lingual) has some formatting or characters that is breaking out of XML and malforming the object.

I will try to get a copy of the mail from one the 13 users who got it and see if I can identify the issue.

[leonjza]

Please paste the broken XML here as well as the mail messageID. Can try poke someone at CCP if needed.

[zantharax]

It's an alliance mail, so I can't post it directly on here, but I the mail ID is 357801633.

This is a CCP problem for sure though - direct api queries for the mail generate errors. From the browser:

This page contains the following errors:

error on line 6 at column 343: Input is not proper UTF-8, indicate encoding !
Bytes: 0x0C 0x3C 0x62 0x72
Below is a rendering of the page up to the first error.

From a web-based parser: Unable to parse any XML input. org.jdom2.input.JDOMParseException: Error on line 6: An invalid XML character (Unicode: 0xc) was found in the CDATA section.

[leonjza]

Had a chat to CCP Tellus about this one, and there was no real indication on whether this will be looked at, yet alone fixed. So, for now I am going to wrap the error and just try handle in gracefully for now.