Project

General

Profile

Bug #13655

nmbd generates gigabytes of logs

Added by Elliott Hillary over 4 years ago. Updated about 3 years ago.

Status:
Closed: Behaves correctly
Priority:
No priority
Assignee:
John Hixson
Category:
OS
Target version:
Seen in:
Severity:
New
Reason for Closing:
Reason for Blocked:
Needs QA:
Yes
Needs Doc:
Yes
Needs Merging:
Yes
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:
ChangeLog Required:
No

Description

(Possibly the same bug as https://bugs.pcbsd.org/issues/3755)

Last week nmbd began generating thousands of log messages per second and the machine became unresponsive.

$ ls -lh /var/log/ | grep messages
-rw-------  1 root  wheel      89k Feb 16 21:39 messages
-rw-r--r--  1 root  wheel       5G Feb  7 00:00 messages.0.bz2
-rw-r--r--  1 root  wheel     1.6G Feb  6 00:00 messages.1.bz2
-rw-r--r--  1 root  wheel      12k Feb  5 00:00 messages.2.bz2
-rw-r--r--  1 root  wheel      14k Jan 26 00:00 messages.3.bz2
-rw-r--r--  1 root  wheel      10k Jan 16 00:00 messages.4.bz2

I believe that the cause of the problem was that my powerline adapter died, cutting the FreeNAS machine off from (most of) the rest of the network, including the router. I fixed the problem with the powerline adapter, but the log messages continued. The following messages are repeated constantly:

$ zcat /var/log/messages.0.bz2 | head 
Feb  6 00:00:00 pyrite newsyslog[78490]: logfile turned over due to size>100K
Feb  6 00:00:00 pyrite syslog-ng[1952]: Configuration reload request received, reloading configuration;
Feb  6 00:00:00 pyrite nmbd[2793]:   nmbd_subnetdb:make_subnet()
Feb  6 00:00:00 pyrite nmbd[2793]:     Failed to open nmb bcast socket on interface 0.255.255.255 for port 137.  Error was Can't assign requested address
Feb  6 00:00:00 pyrite nmbd[2793]: [2016/02/06 00:00:00.341078,  0] ../source3/lib/util_sock.c:485(open_socket_in)
Feb  6 00:00:00 pyrite nmbd[2793]:   bind failed on port 137 socket_addr = 0.255.255.255.
Feb  6 00:00:00 pyrite nmbd[2793]:   Error = Can't assign requested address
Feb  6 00:00:00 pyrite nmbd[2793]: [2016/02/06 00:00:00.341091,  0] ../source3/nmbd/nmbd_subnetdb.c:127(make_subnet)
Feb  6 00:00:00 pyrite nmbd[2793]:   nmbd_subnetdb:make_subnet()
Feb  6 00:00:00 pyrite nmbd[2793]:     Failed to open nmb bcast socket on interface 0.255.255.255 for port 137.  Error was Can't assign requested address

I managed to switch to a tty and issue a reboot, and everything seemed to operate as normal after that. I've since noticed that the CPU has been pegged at 100% on two cores for the pass week whilst telemetry-gather.py goes over the logs.

$ ps auxww | head
USER         PID  %CPU %MEM     VSZ    RSS TT  STAT STARTED        TIME COMMAND
root          11 599.4  0.0       0    128 ??  RL    6Feb16 89472:01.13 [idle]
root       29645 100.0  0.0   89748   8084 ??  R     8Feb16 12675:04.48 /usr/local/bin/python /usr/local/bin/telemetry-gather.py /var/log/messages /var/log/messages.0.bz2 /var/log/messages.1.bz2 /var/log/messages.2.bz2 /var/log/messages.3.bz2 /var/log/messages.4.bz2 (python2.7)
root       52363 100.0  0.0   90004   8096 ??  R     7Feb16 14107:43.09 /usr/local/bin/python /usr/local/bin/telemetry-gather.py /var/log/messages /var/log/messages.0 /var/log/messages.0.bz2 /var/log/messages.1.bz2 /var/log/messages.2.bz2 /var/log/messages.3.bz2 /var/log/messages.4.bz2 (python2.7)
816         8050   0.8  0.8  438248 132036 ??  SsJ   6Feb16    44:55.40 /usr/pbi/sonarr-amd64/bin/mono /usr/pbi/sonarr-amd64/share/sonarr/NzbDrone/NzbDrone.exe --data=/var/db/sonarr --nobrowser (mono-sgen)
root           0   0.0  0.1       0   8608 ??  DLs   6Feb16   109:30.55 [kernel]
root           1   0.0  0.0    6276    128 ??  ILs   6Feb16     0:00.67 /sbin/init --
root           2   0.0  0.0       0     16 ??  DL    6Feb16     0:00.00 [crypto]
root           3   0.0  0.0       0     16 ??  DL    6Feb16     0:00.00 [crypto returns]
root           4   0.0  0.0       0     16 ??  DL    6Feb16     0:01.01 [mps_scan0]

This issue has happened to me about four times in the last six months, always after I've had networking troubles of some description.

I'm not sure whether turning off logging like the outcome of the previous ticket would indicate is the answer, as I don't know if the system recovers after it has entered this state, but I can try that and see if I can reproduce the problem after if required.

Anything else you'd like me to provide, please let me know.

History

#1 Updated by John Hixson over 4 years ago

  • Status changed from Unscreened to Closed: Behaves correctly
  • Target version set to 261

Elliott Hillary wrote:

(Possibly the same bug as https://bugs.pcbsd.org/issues/3755)

Last week nmbd began generating thousands of log messages per second and the machine became unresponsive.

----
$ ls lh /var/log/ | grep messages
-rw------
1 root wheel 89k Feb 16 21:39 messages
rw-r--r- 1 root wheel 5G Feb 7 00:00 messages.0.bz2
rw-r--r- 1 root wheel 1.6G Feb 6 00:00 messages.1.bz2
rw-r--r- 1 root wheel 12k Feb 5 00:00 messages.2.bz2
rw-r--r- 1 root wheel 14k Jan 26 00:00 messages.3.bz2
rw-r--r- 1 root wheel 10k Jan 16 00:00 messages.4.bz2
----

I believe that the cause of the problem was that my powerline adapter died, cutting the FreeNAS machine off from (most of) the rest of the network, including the router. I fixed the problem with the powerline adapter, but the log messages continued. The following messages are repeated constantly:

----
$ zcat /var/log/messages.0.bz2 | head
Feb 6 00:00:00 pyrite newsyslog78490: logfile turned over due to size>100K
Feb 6 00:00:00 pyrite syslog-ng1952: Configuration reload request received, reloading configuration;
Feb 6 00:00:00 pyrite nmbd2793: nmbd_subnetdb:make_subnet()
Feb 6 00:00:00 pyrite nmbd2793: Failed to open nmb bcast socket on interface 0.255.255.255 for port 137. Error was Can't assign requested address
Feb 6 00:00:00 pyrite nmbd2793: [2016/02/06 00:00:00.341078, 0] ../source3/lib/util_sock.c:485(open_socket_in)
Feb 6 00:00:00 pyrite nmbd2793: bind failed on port 137 socket_addr = 0.255.255.255.
Feb 6 00:00:00 pyrite nmbd2793: Error = Can't assign requested address
Feb 6 00:00:00 pyrite nmbd2793: [2016/02/06 00:00:00.341091, 0] ../source3/nmbd/nmbd_subnetdb.c:127(make_subnet)
Feb 6 00:00:00 pyrite nmbd2793: nmbd_subnetdb:make_subnet()
Feb 6 00:00:00 pyrite nmbd2793: Failed to open nmb bcast socket on interface 0.255.255.255 for port 137. Error was Can't assign requested address
----

I managed to switch to a tty and issue a reboot, and everything seemed to operate as normal after that. I've since noticed that the CPU has been pegged at 100% on two cores for the pass week whilst telemetry-gather.py goes over the logs.

----
$ ps auxww | head
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
root 11 599.4 0.0 0 128 ?? RL 6Feb16 89472:01.13 [idle]
root 29645 100.0 0.0 89748 8084 ?? R 8Feb16 12675:04.48 /usr/local/bin/python /usr/local/bin/telemetry-gather.py /var/log/messages /var/log/messages.0.bz2 /var/log/messages.1.bz2 /var/log/messages.2.bz2 /var/log/messages.3.bz2 /var/log/messages.4.bz2 (python2.7)
root 52363 100.0 0.0 90004 8096 ?? R 7Feb16 14107:43.09 /usr/local/bin/python /usr/local/bin/telemetry-gather.py /var/log/messages /var/log/messages.0 /var/log/messages.0.bz2 /var/log/messages.1.bz2 /var/log/messages.2.bz2 /var/log/messages.3.bz2 /var/log/messages.4.bz2 (python2.7)
816 8050 0.8 0.8 438248 132036 ?? SsJ 6Feb16 44:55.40 /usr/pbi/sonarr-amd64/bin/mono /usr/pbi/sonarr-amd64/share/sonarr/NzbDrone/NzbDrone.exe --data=/var/db/sonarr --nobrowser (mono-sgen)
root 0 0.0 0.1 0 8608 ?? DLs 6Feb16 109:30.55 [kernel]
root 1 0.0 0.0 6276 128 ?? ILs 6Feb16 0:00.67 /sbin/init --
root 2 0.0 0.0 0 16 ?? DL 6Feb16 0:00.00 [crypto]
root 3 0.0 0.0 0 16 ?? DL 6Feb16 0:00.00 [crypto returns]
root 4 0.0 0.0 0 16 ?? DL 6Feb16 0:01.01 [mps_scan0]
----

This issue has happened to me about four times in the last six months, always after I've had networking troubles of some description.

I'm not sure whether turning off logging like the outcome of the previous ticket would indicate is the answer, as I don't know if the system recovers after it has entered this state, but I can try that and see if I can reproduce the problem after if required.

Anything else you'd like me to provide, please let me know.

I don't see the bug here. You had a network issue and samba complained accordingly. I would turn off or turn down logging if you don't want things to be logged ;-)

#2 Updated by Elliott Hillary over 4 years ago

John Hixson wrote:

I don't see the bug here. You had a network issue and samba complained accordingly. I would turn off or turn down logging if you don't want things to be logged ;-)

Well, I don't know that I consider thousands of messages per second to be "accordingly", and it seemed to continue after the networking issues were resolved, but I take your point. :-)

In that case, I guess the problem isn't the logs from nmbd, so much as the fact that the unexpectedly large amount of logs causes other problems elsewhere, like the telemetry-gather.py problem.

In fact, when submitting the above bug report from the FreeNAS web UI, it got killed while collecting debug info and now the web interface is dead.

Feb 16 22:26:41 pyrite manage.py: [common.pipesubr:71] Popen()ing: /usr/local/bin/ixdiagnose -d /var/db/system/ixdiagnose -s -F
Feb 16 22:36:25 pyrite swap_pager_getswapspace(16): failed
Feb 16 22:36:25 pyrite swap_pager_getswapspace(16): failed
Feb 16 22:36:25 pyrite swap_pager_getswapspace(12): failed
Feb 16 22:36:25 pyrite swap_pager_getswapspace(16): failed
Feb 16 22:36:25 pyrite swap_pager_getswapspace(12): failed
Feb 16 22:36:25 pyrite swap_pager_getswapspace(6): failed
Feb 16 22:36:25 pyrite swap_pager_getswapspace(16): failed
Feb 16 22:36:25 pyrite swap_pager_getswapspace(12): failed
Feb 16 22:36:25 pyrite swap_pager_getswapspace(9): failed
Feb 16 22:36:25 pyrite swap_pager_getswapspace(16): failed
Feb 16 22:36:26 pyrite kernel: pid 3116 (python2.7), uid 0, was killed: out of swap space
Feb 16 22:36:26 pyrite kernel: pid 3116 (python2.7), uid 0, was killed: out of swap space

Should I recategorise this as Logging?

#3 Updated by Elliott Hillary over 4 years ago

  • Description updated (diff)

#4 Avatar?id=14398&size=24x24 Updated by Kris Moore about 4 years ago

  • Target version changed from 261 to N/A

#5 Avatar?id=14398&size=24x24 Updated by Kris Moore about 4 years ago

  • Seen in changed from Unspecified to N/A

#6 Updated by Dru Lavigne about 3 years ago

  • Private changed from Yes to No

Also available in: Atom PDF