1

The gist of our problem is that we lose ssh access to our VPS and our logfiles get all mixed up. Doing a hard reboot through our hosting provider's web console seems to fix things, but the problem recurs.

More Details

This seems to occur somewhat randomly, about once every two weeks. The symptom we usually notice first is that we can't log in via ssh; strangely the server still prompts us for a password but never lets us log in. Apache keeps on trucking, but other system services die off as well.

At the time of the "error events" we get a ton of random-looking garbage in all of our logfiles (everything in /var/log as well as Apache's virtual host logs and others). The garbage contains a lot of null bytes, some unicode binary-looking stuff, big blocks of random ASCII, parts of other logfiles, and css/javascript (see examples below). It kind of seems like it's writing the buffer cache into currently-open files, but I have no idea why or even how this would happen. Fedora uses syslogd for logging, but I was unable to find any obvious problems there.

Our server is a VPS running Fedora 12. Its main duties are running Apache, Postfix and ssh. The sites Apache is serving use PHP/MySQL (the last time this happened I installed the Suhosin patch in case this is a weird buffer overflow attack or somesuch).

We have secure passwords for our ssh/htpasswd users and the logs (the parts we can read anyway) do not indicate that our server has been compromised "from the inside".

Example Borked Logfiles

Here's a snippet from our cron log. This one has a bunch of null bytes and other binary-looking data, but as mentioned above some other files contain ASCII and/or chunks of other files:

Sep 23 03:05:01 HostName CROND[3208]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 03:05:01 HostName CROND[3209]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 03:10:01 HostName CROND[3792]: (root) CMD (/usr/lib64/sa/sa1 -S DISK 1 1)
Sep 23 03:10:01 HostName CROND[3795]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 03:10:01 HostName CROND[3793]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 03:15:01 HostName CROND[4414]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 03:15:01 HostName CROND[4415]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 03:20:01 HostName CROND[5000]: (root) CMD (/usr/lib64/sa/sa1 -S DISK 1 1)
Sep 23 03:20:01 HostName CROND[5001]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 03:20:01 HostName CROND[5003]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 03:25:01 HostName CROND[5590]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 03:25:01 HostName CROND[5591]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 03:30:01 HostName CROND[6175]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 03:30:01 HostName CROND[6174]: (root) CMD (/usr/lib64/sa/sa1 -S DISK 1 1)
Sep 23 03:30:01 HostName CROND[6176]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 03:35:01 HostName CROND[6763]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 03:35:01 HostName CROND[6764]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 03:40:01 HostName CROND[7347]: (root) CMD (/usr/lib64/sa/sa1 -S DISK 1 1)
Sep 23 03:40:01 HostName CROND[7349]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 03:40:01 HostName CROND[7350]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^$


����.]������^[�Z��� ��H*[ݬ^T�՜^F�Ük֜�՜0�|��Ԝ0��5�֜+�^\J̜aMݺu3^]�'M��I�&�[�n^Vdz�&""^RȳZ�uݳݳʳ��۳g:h��;�5^U;k�j�C��Rj�C ^Zv��Ρġ^\֡T]]���2^@@aa!���Q^^nq�]v֛7oƚ5k`4^Z1^?�|^D^E^E!22^R���P�TX�n��aޚwbgM$
^KQ�����l4U�;���e��v�� 7u֯7oޯDVV^V j5������^O�Vk���5^Q^QI%���ͱ�α�ƍ^[�� ^O􁏏z=BBB���^L^@HIIAHH�ŁZ^����9䁏^[/��9䁏�၏�^y灏Pb^Nk2^X^Lȁ́́DJJ
RRR���^E��`q�]v֛7oƇ^_~^H�ш ^{^MAAA�7o^^T*^U����v�Zx�vψ ;��&""���9k777t�ވ^]^@p��E���`����ƈوug���ψ��ѣ8v�^X"""����={�`ǎ^]ؽ{�Ž^C5�νZν^Z��o��^Z搷�^]��s(1�5ՐԐԐ�ېې^[NNNprr���Oː묛��5^Q^QIŬ笛Y7^Sv֬�լ0$
�֭����٭zv֭DD$^U�g-PFF��Wdd$����!&&^F^Q^Q^QHMMEDD^D���-ֳ����9�^[/��9��aG*�^\J̳aM��eݭ[7������s��yDGGc۶m�ѣ^GN�<��^];���^P���У�tf�أY^S^Q�T�f-Rtt4ޣ~�m888@�ףãݣݣ^]^@�V�Q\\|ף���"�$$��ң%���^B���^Z�Fԣx^@$
�N^G�N���0��� ,,^Lyyy^V��Y�W�^\���R�^\�ְ#�w^N%氦�gX߰��^V�<밦尦˗×h4bɒ%HJJBZZ^Z*++1~�x̚5^K���HII��M�,ֳ�&"")��9볦ʳʳJ^\<x^P���P�T8q⳦^D^^~� zc춳� �쫯�ϫ^B^@�~�i�髯O^?Bjj*«ëë^A^@   Hk૯_K쫯�嫯�a^N�ƫK�a$
����6m^Z�n݊�{�"11ъl=�Y^S^Q�T�7�@�W�Ɗܹs1nܹ8DFFb���CRR^R�L���^[7"66 b=�YˈWÈ^\ ��RÈ^\  �Z��s(1�-و]g݈T쬉�H*v֬̈́��|5̄!߄x)5̄!o^M;Ry焉Pb^N[bgMDD$^P;넉f^Ä΄Z�^Z愉�o��^Z搷�^]��s(1�-��&""^R���̪���Ӫ骷p� e^@@nn��$
6m�d���5^Q^QI��κW�^X�z5


^P^U^U���^@�={^Vyyy6;P^C�/���C�^N����ǰað�ӰO?!55^U���^@���p�5��%vְ�հ0�|�� 0��5�H��C�9l��7�988�ٰg�ŢE�����b��͢0^Z�͵6������˵/#//^O�f͵µ���� ����^N^@P�յ(..�����^H%              p6^XP��
^@������^Z^O^@]~;^M/t<jkE���.�`^N����Ď/MM�Kp0s؎q^NCa!J^R^RP����f�4��_~�?���pvvƎ�ի1a«^D� ^_;v��^[o�^A__ f_��***Э[78;;#++^Kj�^ZEEE����V�5[^S^U^U���x�sh4^ZѭYŭ֔���%8X֔9��9䘣�䘣�R#e^N�Y�CY9^@ؘ옣4�$
�֭����٭:v֭DD$^U;k^Q����r�J���^A^@bbb^P^Q^Q�  TDDD ::ڭb-;k�j�C��Rj�Cޭ^Zv��Ρġ^\�dw���`��9s�t�R^L^\8^P%%%���¡ɓ'ѱcG^T^V^V±߱߱^_:�αl=;k""����@˖-CDD^D|||Lۖ�z=ܖݖݖ^A^@j�^ZŖŖŖwՖՖ^T^U�$!^A��.�zظF�^Q�и�ܸm۸D��$
^@������^Z^O^@]~;^M/t<jkE���.�`^N����Ď/MM�Kp0s؎q^NCa!J^R^RP����fw��븺���d///deeA�V���^H���иj�f뢢�^P^_^_/x^^�F^C___Qk^S[S��^F� `Y碢`^N梢�c���CJ��9Ģfa^Ne墢^@`�Ӣ -⢢`=s梢L���cڴiغu+� ċċD�u�fMDD$
^K^K���o�9.\�`��Mk�j�Y7�M�6pr����e˖!""^B>>>�Y�^D�r8;;���_F^^^^f͚����ۚhu^Ù˙q�^Ù^E|�ə'� ^SF�^\�+W�ةhu^Ù˙Q'::^Zo����^OԀ�^\+W�Āرc1nܱ8�8C^@�ϱ2p�@|�ٱg����DZ^_^?�^[7nرhu±^M^[6^L>>>8~�8�y�^Yıűű5x�(�2��$
Sep 23 20:11:21 HostName crond[1077]: (CRON) INFO (running with inotify support)
Sep 23 20:15:01 HostName CROND[1578]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 20:15:01 HostName CROND[1579]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 20:20:01 HostName CROND[2192]: (root) CMD (/usr/lib64/sa/sa1 -S DISK 1 1)
Sep 23 20:20:01 HostName CROND[2193]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 20:20:01 HostName CROND[2194]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 20:25:01 HostName CROND[2841]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 20:25:01 HostName CROND[2843]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 20:30:01 HostName CROND[3432]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 20:30:01 HostName CROND[3433]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 20:30:01 HostName CROND[3436]: (root) CMD (/usr/lib64/sa/sa1 -S DISK 1 1)
Sep 23 20:35:01 HostName CROND[4022]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 20:35:01 HostName CROND[4023]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 20:40:01 HostName CROND[4671]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 20:40:01 HostName CROND[4672]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 20:40:01 HostName CROND[4675]: (root) CMD (/usr/lib64/sa/sa1 -S DISK 1 1)
Sep 23 20:45:01 HostName CROND[5288]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 20:45:01 HostName CROND[5289]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 20:50:01 HostName CROND[5929]: (munin) CMD (test -x /usr/bin/munin-cron && /usr/bin/munin-cron)
Sep 23 20:50:01 HostName CROND[5930]: (user1) CMD (/path/to/development.domain.com/public/protected/yiic serverState)
Sep 23 20:50:01 HostName CROND[5928]: (root) CMD (/usr/lib64/sa/sa1 -S DISK 1 1)

And here's a snippet from our site's application.log (we use the Yii Framework and this is where application-level logging occurs). This one includes chunks of other files (logfiles, svn metadata, and more), binary data, ASCII, etc.

Has anyone ever seen anything like this?

Improve this question

2 Answers 2

Reset to default
2

There are a lot of unknowns in this, but I'm thinking filesystem failure.

A running daemon may have enough things cached in ram to accept the connection but not to complete a full authentication.

Mixed up files are a strong indicator of the filesystem (or its recovery) going bad. This could be caused by software (experimental kernel/filesystem/...) or hardware. I'm inclined to go with the latter. Run a proper filesystem check and a hardware test on the disk (badblocks, and while you're at it, run memtest86 if you can).

Also, you must consider this b0rking of files may not be limited to logfiles. It could also be in code or databases. I recommend you verify if the data is valid everywhere...

Improve this answer
3
  • We're on a VPS, so there's no access to the physical hardware, and we've been in contact with our provider and they've assured us it isn't a problem on their end.
    – Matt Kantor
    Sep 27, 2010 at 18:09
  • Also, we have worried that it's not limited to logfiles, but we've been unable to find problems in other files that we've looked at. I'm trying to come up with a way to do a full-filesystem search but the randomness of it makes it tough. (What do I search for? Sequences of null-bytes will come up with a ton of false positives.)
    – Matt Kantor
    Sep 27, 2010 at 18:12
  • A VPS does not exclude hardware problems, of course. Nor do assurances of a provider... You could also consider asking them to switch you to entirely different hardware just to make sure (if there is no problem on their end they shouldn't make a problem there). I would try to verify code files against the resources in version control or something, but the best test would be badblocks (from a recovery console)
    – Joris
    Sep 27, 2010 at 18:32
1

Up to the part about filesystem weirdness, your symptoms seem to be exactly those of running out of RAM. SSH gives you a prompt since it's already running, but finding memory to spawn a new process is slow. And system services die off because they are zapped by the OOM-killer. Are any references to that in the logs?

Do you have any metrics on memory usage or system load, preferably recorded externally to the problematic machine?

It would be extremely helpful to have remote logging, too — then you could see if any vital clues are being overwritten by the file corruption. Fedora uses rsyslogd, and the rsyslog site has instructions on setting that up securely.

Improve this answer

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .