Project

General

Profile

Bug #27775

Unauthorized system reboot

Added by Marco Palomba over 3 years ago. Updated over 3 years ago.

Status:
Closed
Priority:
No priority
Assignee:
Timur Bakeyev
Category:
OS
Target version:
Seen in:
Severity:
New
Reason for Closing:
User Configuration Error
Reason for Blocked:
Needs QA:
Yes
Needs Doc:
Yes
Needs Merging:
Yes
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:

HP Microserver gen8 - 8GB ram ecc
4HD - 3TB WD RED

ChangeLog Required:
No

Description

Hi,
i'm a newbie. This is my first post!

Tonight i received 8 of this kind of message from my FreeNas:
"freenas.xxx.local: Unauthorized system reboot
System booted at Fri Jan 12 06:13:41 2018 was not shut down properly"

What's happened? It's seem that FreeNas rebooted by itself.

This is the 2 time that occour, 10 days between last time.
Probably it happened after i upgrade to 11.1 release.
When i have 11.0-U4 this problem doesn't occour.

Can you help me please?

Thanks a lot.


Related issues

Related to FreeNAS - Bug #27514: Break potential recursion involving getnewvnode and zfs_rmnodeDone

History

#1 Updated by Dru Lavigne over 3 years ago

  • Status changed from Unscreened to 15
  • Private changed from No to Yes

Marco: please attach a debug (System -> Advanced -> Save Debug).

#2 Updated by Marco Palomba over 3 years ago

  • File debug-freenas-20180116175718.tgz added

Hi,
this is my debug.

#3 Updated by Dru Lavigne over 3 years ago

  • Status changed from 15 to Unscreened
  • Assignee changed from Release Council to Timur Bakeyev
  • Target version set to 11.1-U2

Passing to Timur first as middlewared is complaining about not finding the domain server.

#4 Updated by Marco Palomba over 3 years ago

  • Seen in changed from 11.1 to 11.1-U2

In the past I tried to configure the synchronization with AD, but during the configuration I realized that I did not really need it, so I never activated it.
Despite having disabled the synchronization with AD in the log I received warning messages, which warned me that the synchronization with AD had failed.
However for now I'm not interested in synchronizing users with AD.

#5 Updated by Dru Lavigne over 3 years ago

  • Seen in changed from 11.1-U2 to 11.1

#6 Updated by Timur Bakeyev over 3 years ago

  • Related to Bug #27514: Break potential recursion involving getnewvnode and zfs_rmnode added

#7 Updated by Timur Bakeyev over 3 years ago

  • Status changed from Unscreened to 15

Hi, Marco!

There are a lot of various errors I can see in the logs and it's a bit hard to spot what actually caused the problem.

The direct cause of the reboots is the running out of memory, even the swap space:

Jan 18 04:15:39 freenasedb swap_pager_getswapspace(15): failed
Jan 18 04:15:39 freenasedb swap_pager_getswapspace(15): failed
Jan 18 04:15:39 freenasedb swap_pager_getswapspace(15): failed

The most affected seems to be the Samba process:

Jan 18 05:11:42 freenasedb kernel: pid 26855 (smbd), uid 46453, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 26855 (smbd), uid 46453, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 26835 (smbd), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 26835 (smbd), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 26880 (smbd), uid 0, was killed: out of swap space

But it's hard to say, why did it grow so much.

What looks VERY suspicious are those line:

swap_pager_getswapspace(15): failed
swap_pager_getswapspace(8): failed
swap_pager_getswapspace(15): failed
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (1 occurrences)
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (2392 occurrences)
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (2392 occurrences)
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (2392 occurrences)
pid 15149 (smbd), uid 46453, was killed: out of swap space
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (536 occurrences)
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (4 occurrences)
Limiting closed port RST response from 1094 to 200 packets/sec
Limiting closed port RST response from 1237 to 200 packets/sec
Limiting closed port RST response from 1240 to 200 packets/sec
Limiting closed port RST response from 1217 to 200 packets/sec
Limiting closed port RST response from 1219 to 200 packets/sec
Limiting closed port RST response from 1212 to 200 packets/sec
Limiting closed port RST response from 1214 to 200 packets/sec
Limiting closed port RST response from 343 to 200 packets/sec
Limiting closed port RST response from 1236 to 200 packets/sec
Limiting closed port RST response from 1217 to 200 packets/sec
Limiting closed port RST response from 735 to 200 packets/sec
Limiting closed port RST response from 1216 to 200 packets/sec
Limiting closed port RST response from 1229 to 200 packets/sec
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (3 occurrences)
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (9 occurrences)
Limiting closed port RST response from 1118 to 200 packets/sec
Limiting closed port RST response from 1230 to 200 packets/sec
Limiting closed port RST response from 1239 to 200 packets/sec

Also I see:

Dec 21 15:49:56 freenasedb uwsgi: [django.security.DisallowedHost:73] Invalid HTTP_HOST header: "'%2Bconvert(varchar%2C0x7b5d)%2B'". The domain name provided is not valid according to RFC 1034/1035.
Dec 21 15:49:56 freenasedb uwsgi: [django.security.DisallowedHost:73] Invalid HTTP_HOST header: "nessus='%2Bconvert(varchar%2C0x7b5d)%2B'". The domain name provided is not valid according to RFC 1034/1035.
Dec 21 15:49:57 freenasedb uwsgi: [django.security.DisallowedHost:73] Invalid HTTP_HOST header: 'convert(int,convert(varchar%2C0x7b5d))'. The domain name provided is not valid according to RFC 1034/1035.
Dec 21 15:49:57 freenasedb uwsgi: [django.security.DisallowedHost:73] Invalid HTTP_HOST header: 'nessus=convert(int,convert(varchar%2C0x7b5d))'. The domainname provided is not valid according to RFC 1034/1035.
......
Jan  6 05:22:54 freenasedb uwsgi: [django.security.DisallowedHost:73] Invalid HTTP_HOST header: "nessus=whatever='". The domain name provided is not valid according to RFC 1034/1035.
Jan  6 05:22:54 freenasedb uwsgi: [django.security.DisallowedHost:73] Invalid HTTP_HOST header: 'whatever="'. The domain name provided is not valid according to RFC 1034/1035.
Jan  6 05:22:54 freenasedb uwsgi: [django.security.DisallowedHost:73] Invalid HTTP_HOST header: 'nessus=whatever="'. The domain name provided is not valid according to RFC 1034/1035.
.......
Jan 10 15:11:04 freenasedb sshd[88516]: in openpam_check_error_code(): pam_sm_setcred(): unexpected return value 12
Jan 10 15:11:04 freenasedb sshd[88516]: in openpam_check_error_code(): pam_sm_setcred(): unexpected return value 12
Jan 10 15:11:04 freenasedb syslog-ng[83085]: I/O error occurred while writing; fd='24', error='Connection refused (61)
Jan 10 15:11:05 freenasedb sshd[88521]: in openpam_check_error_code(): pam_sm_setcred(): unexpected return value 12
Jan 10 15:11:05 freenasedb sshd[88521]: in openpam_check_error_code(): pam_sm_setcred(): unexpected return value 12
Jan 10 15:11:05 freenasedb sshd[88526]: in openpam_check_error_code(): pam_sm_setcred(): unexpected return value 12
Jan 10 15:11:05 freenasedb sshd[88526]: in openpam_check_error_code(): pam_sm_setcred(): unexpected return value 12
Jan 10 15:11:05 freenasedb sshd[88533]: in openpam_check_error_code(): pam_sm_setcred(): unexpected return value 12
Jan 10 15:11:05 freenasedb sshd[88533]: in openpam_check_error_code(): pam_sm_setcred(): unexpected return value 12
Jan 10 15:12:04 freenasedb sshd[88696]: in openpam_check_error_code(): pam_sm_setcred(): unexpected return value 12
Jan 10 15:12:04 freenasedb sshd[88696]: in openpam_check_error_code(): pam_sm_setcred(): unexpected return value 12
Jan 10 15:12:05 freenasedb sshd[88701]: in openpam_check_error_code(): pam_sm_setcred(): unexpected return value 12
Jan 10 15:12:05 freenasedb sshd[88701]: in openpam_check_error_code(): pam_sm_setcred(): unexpected return value 12
......
Jan 10 16:03:26 freenasedb syslog-ng[1752]: I/O error occurred while writing; fd='27', error='Connection refused (61)'
pid 17779 (smbd), uid 0: exited on signal 6 (core dumped)
pid 17801 (smbd), uid 0: exited on signal 6 (core dumped)
pid 17830 (smbd), uid 0: exited on signal 6 (core dumped)
pid 17856 (smbd), uid 0: exited on signal 6 (core dumped)
pid 17876 (smbd), uid 0: exited on signal 6 (core dumped)
.....
pid 37690 (smbd), uid 0: exited on signal 6 (core dumped)
pid 37703 (smbd), uid 0: exited on signal 6 (core dumped)
pid 37716 (smbd), uid 0: exited on signal 6 (core dumped)
pid 37729 (smbd), uid 0: exited on signal 6 (core dumped)
pid 37744 (smbd), uid 0: exited on signal 6 (core dumped)
Jan 10 16:53:02 freenasedb shutdown: reboot by root:
......
swap_pager_getswapspace(15): failed
swap_pager_getswapspace(8): failed
swap_pager_getswapspace(15): failed
Jan 12 20:15:43 snmpd[3962]: Connection from UDP: [10.1.11.67]:49941->[10.3.11.3]:161
Jan 12 20:15:47 snmpd[3962]: Connection from UDP: [10.1.11.67]:49941->[10.3.11.3]:161
Jan 12 20:15:51 snmpd[3962]: Connection from UDP: [10.1.11.67]:49941->[10.3.11.3]:161
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (1 occurrences)
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (2392 occurrences)
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (2392 occurrences)
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (2392 occurrences)
Jan 12 21:15:43 snmpd[3962]: Connection from UDP: [10.1.11.67]:52632->[10.3.11.3]:161
Jan 12 21:15:47 snmpd[3962]: Connection from UDP: [10.1.11.67]:52632->[10.3.11.3]:161
Jan 12 21:15:51 snmpd[3962]: Connection from UDP: [10.1.11.67]:52632->[10.3.11.3]:161
pid 15149 (smbd), uid 46453, was killed: out of swap space
Jan 12 22:15:40 snmpd[3962]: Connection from UDP: [10.1.11.67]:52114->[10.3.11.3]:161
Jan 12 22:15:44 snmpd[3962]: Connection from UDP: [10.1.11.67]:52114->[10.3.11.3]:161
Jan 12 22:15:48 snmpd[3962]: Connection from UDP: [10.1.11.67]:52114->[10.3.11.3]:161
Jan 12 23:15:42 snmpd[3962]: Connection from UDP: [10.1.11.67]:55890->[10.3.11.3]:161
Jan 12 23:15:46 snmpd[3962]: Connection from UDP: [10.1.11.67]:55890->[10.3.11.3]:161
Jan 12 23:15:50 snmpd[3962]: Connection from UDP: [10.1.11.67]:55890->[10.3.11.3]:161
Jan 13 00:00:39 snmpd[3962]: Connection from UDP: [10.1.11.67]:50754->[10.3.11.3]:161
Jan 13 00:00:43 snmpd[3962]: Connection from UDP: [10.1.11.67]:50754->[10.3.11.3]:161
Jan 13 00:00:47 snmpd[3962]: Connection from UDP: [10.1.11.67]:50754->[10.3.11.3]:161
Jan 13 00:01:43 snmpd[3962]: Connection from UDP: [10.1.11.67]:60482->[10.3.11.3]:161
Jan 13 00:01:47 snmpd[3962]: Connection from UDP: [10.1.11.67]:60482->[10.3.11.3]:161
Jan 13 00:01:51 snmpd[3962]: Connection from UDP: [10.1.11.67]:60482->[10.3.11.3]:161
Jan 13 00:15:42 snmpd[3962]: Connection from UDP: [10.1.11.67]:55079->[10.3.11.3]:161
Jan 13 00:15:46 snmpd[3962]: Connection from UDP: [10.1.11.67]:55079->[10.3.11.3]:161
Jan 13 00:15:50 snmpd[3962]: Connection from UDP: [10.1.11.67]:55079->[10.3.11.3]:161
Limiting closed port RST response from 1196 to 200 packets/sec
Limiting closed port RST response from 1211 to 200 packets/sec
Limiting closed port RST response from 358 to 200 packets/sec
Limiting closed port RST response from 1229 to 200 packets/sec
Limiting closed port RST response from 1221 to 200 packets/sec
Limiting closed port RST response from 738 to 200 packets/sec
Limiting closed port RST response from 1232 to 200 packets/sec
Limiting closed port RST response from 1243 to 200 packets/sec
Jan 15 07:15:55 snmpd[3962]: Connection from UDP: [10.1.11.67]:54323->[10.3.11.3]:161
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (4 occurrences)
Jan 15 08:15:45 snmpd[3962]: Connection from UDP: [10.1.11.67]:58600->[10.3.11.3]:161
Jan 15 08:15:49 snmpd[3962]: Connection from UDP: [10.1.11.67]:58600->[10.3.11.3]:161
Jan 15 08:15:53 snmpd[3962]: Connection from UDP: [10.1.11.67]:58600->[10.3.11.3]:161
sonewconn: pcb 0xfffff80049ff83a0: Listen queue overflow: 76 already in queue awaiting acceptance (174 occurrences)
.....
Jan 18 05:11:42 freenasedb kernel: pid 26896 (smbd), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 26896 (smbd), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 3714 (smbd), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 3714 (smbd), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 3725 (smbd), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 3725 (smbd), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 3724 (smbd), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 3724 (smbd), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 26901 (smbd), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 26901 (smbd), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 5065 (uwsgi), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb kernel: pid 5065 (uwsgi), uid 0, was killed: out of swap space
Jan 18 05:11:42 freenasedb syslog-ng[1739]: I/O error occurred while writing; fd='21', error='Connection refused (61)'
Jan 18 05:11:43 freenasedb /alert.py: [system.alert:400] Alert module '<samba4.Samba4Alert object at 0x817a79d30>' failed: Failed connection handshake
Jan 18 12:38:44 freenasedb syslog-ng[1739]: I/O error occurred while writing; fd='5', error='Connection refused (61)'
Jan 18 12:40:54 freenasedb syslog-ng[1739]: I/O error occurred while writing; fd='5', error='Connection refused (61)'
Jan 18 12:52:08 freenasedb syslog-ng[1739]: I/O error occurred while writing; fd='21', error='Connection refused (61)'
Jan 18 12:54:19 freenasedb syslog-ng[1739]: I/O error occurred while writing; fd='21', error='Connection refused (61)'
Jan 18 12:57:27 freenasedb syslog-ng[1739]: I/O error occurred while writing; fd='5', error='Connection refused (61)'

All those log messages are indicating that your server is heavily scanned by some external parities. I'm not sure is it you doing that or there is some evil host in your intranet or you expose the server to the Internet, but basically you've been flooded by scans and, seems, some services are not able to coop with it and either die or consume all the memory or misbehave some other way.

So, I suggest you to make sure that there are no scans happening against your FN server.

Also, I couldn't find the Samba logs for the 10 of January in the debug log. That doesn't help to figure out what made smbd process to die.

And, as a side note - despite your comment it seems that your AD bindings are active and actually do some work. Not sure if you really want them on.

#8 Updated by Timur Bakeyev over 3 years ago

  • Related to Bug #27857: Issue when trying to copy snapshot data through "previous versions" added

#9 Updated by Timur Bakeyev over 3 years ago

  • Related to deleted (Bug #27857: Issue when trying to copy snapshot data through "previous versions")

#10 Updated by Timur Bakeyev over 3 years ago

  • Status changed from 15 to Closed
  • Target version changed from 11.1-U2 to N/A
  • Private changed from Yes to No
  • Reason for Closing set to User Configuration Error

#11 Updated by Timur Bakeyev over 3 years ago

  • File deleted (debug-freenas-20180116175718.tgz)

Also available in: Atom PDF