Latest omv/debian updates break collectd/network?

QSx · 8. März 2017

In short, after today's update (it was combined web update of over 20 lib*, new kernel and omv-extras + OMV 3.0.65), collectd keeps hanging/cannot start.

Also there is severe delay in booting (according to log due to network trouble - failure to get ip form dhcp?? - nothing changed on my dhcp, all other machines wired or wireless work fine on my network).

I have pretty vanilla OMV with omv-extras/plex/nut/torrent/sensors plugins - nothing fancy was done to the machine otherwise (hardware or software-wise)

Here's the boot log:

Code

Network hiccup part:
2017-03-08T11:40:28+0100 nas dhclient[1999]: Listening on LPF/eth2/94:de:80:db:45:9b
2017-03-08T11:40:28+0100 nas sh[1953]: Listening on LPF/eth2/94:de:80:db:45:9b
2017-03-08T11:40:28+0100 nas sh[1953]: Sending on   LPF/eth2/94:de:80:db:45:9b
2017-03-08T11:40:28+0100 nas sh[1953]: Sending on   Socket/fallback
2017-03-08T11:40:28+0100 nas sh[1953]: DHCPREQUEST on eth2 to 255.255.255.255 port 67
2017-03-08T11:40:28+0100 nas dhclient[1999]: Sending on   LPF/eth2/94:de:80:db:45:9b
2017-03-08T11:40:28+0100 nas dhclient[1999]: Sending on   Socket/fallback
2017-03-08T11:40:28+0100 nas dhclient[1999]: DHCPREQUEST on eth2 to 255.255.255.255 port 67
2017-03-08T11:40:28+0100 nas systemd[1]: Started Network Time Synchronization.
2017-03-08T11:40:28+0100 nas systemd[1]: Reached target System Time Synchronized.
2017-03-08T11:40:28+0100 nas systemd[1]: Started folder2ram systemd service.
2017-03-08T11:40:30+0100 nas kernel: r8169 0000:02:00.0 eth2: link up
2017-03-08T11:40:33+0100 nas dhclient[1999]: DHCPREQUEST on eth2 to 255.255.255.255 port 67
2017-03-08T11:40:33+0100 nas sh[1953]: DHCPREQUEST on eth2 to 255.255.255.255 port 67
2017-03-08T11:40:33+0100 nas dhclient[1999]: DHCPACK from 10.1.1.1
2017-03-08T11:40:33+0100 nas sh[1953]: DHCPACK from 10.1.1.1
2017-03-08T11:45:28+0100 nas systemd[1]: networking.service: Start operation timed out. Terminating.
2017-03-08T11:45:28+0100 nas systemd[1]: Failed to start Raise network interfaces.
2017-03-08T11:45:28+0100 nas systemd[1]: networking.service: Unit entered failed state.
2017-03-08T11:45:28+0100 nas systemd[1]: networking.service: Failed with result 'timeout'.
2017-03-08T11:45:28+0100 nas systemd[1]: Reached target Network.
2017-03-08T11:45:28+0100 nas systemd[1]: Reached target Network is Online.
2017-03-08T11:45:28+0100 nas systemd[1]: Starting LSB: RPC portmapper replacement...
2017-03-08T11:45:28+0100 nas rpcbind[2302]: Starting rpcbind daemon....
2017-03-08T11:45:28+0100 nas systemd[1]: Started LSB: RPC portmapper replacement.
2017-03-08T11:45:28+0100 nas systemd[1]: Reached target RPC Port Mapper.
2017-03-08T11:45:28+0100 nas systemd[1]: Starting LSB: NFS support files common to client and server...
2017-03-08T11:45:28+0100 nas rpc.statd[2322]: Version 1.2.8 starting
2017-03-08T11:45:28+0100 nas sm-notify[2323]: Version 1.2.8 starting
Monit/collectd failure:
2017-03-08T11:45:48+0100 nas collectd[2570]: Init SSL without certificate database
2017-03-08T11:45:48+0100 nas collectd[2570]: nut plugin: Connection to (localhost, 3493) established.
2017-03-08T11:45:58+0100 nas monit[2521]: 'nas' Monit 5.20.0 started
2017-03-08T11:45:58+0100 nas monit[2521]: 'collectd' process is not running
2017-03-08T11:45:58+0100 nas monit[2521]: 'collectd' trying to restart
2017-03-08T11:45:58+0100 nas monit[2521]: 'collectd' start: '/bin/systemctl start collectd'
2017-03-08T11:46:29+0100 nas monit[2521]: 'collectd' failed to start (exit status 0) -- no output
2017-03-08T11:46:29+0100 nas smbd[2701]: [2017/03/08 11:46:29.328812,  2] ../source3/smbd/server.c:443(remove_child_pid)
2017-03-08T11:46:29+0100 nas smbd[2701]:   Could not find child 3023 -- ignoring
2017-03-08T11:46:59+0100 nas monit[2521]: 'collectd' process is not running
2017-03-08T11:46:59+0100 nas monit[2521]: 'collectd' trying to restart
2017-03-08T11:46:59+0100 nas monit[2521]: 'collectd' start: '/bin/systemctl start collectd'
2017-03-08T11:47:29+0100 nas smbd[2701]: [2017/03/08 11:47:29.382413,  2] ../source3/smbd/server.c:443(remove_child_pid)
2017-03-08T11:47:29+0100 nas smbd[2701]:   Could not find child 3041 -- ignoring
2017-03-08T11:47:29+0100 nas monit[2521]: 'collectd' failed to start (exit status 0) -- no output
2017-03-08T11:47:59+0100 nas monit[2521]: 'collectd' process is not running
2017-03-08T11:47:59+0100 nas monit[2521]: 'collectd' trying to restart
2017-03-08T11:47:59+0100 nas monit[2521]: 'collectd' start: '/bin/systemctl start collectd'
2017-03-08T11:48:29+0100 nas smbd[2701]: [2017/03/08 11:48:29.393184,  2] ../source3/smbd/server.c:443(remove_child_pid)
2017-03-08T11:48:29+0100 nas smbd[2701]:   Could not find child 3057 -- ignoring
2017-03-08T11:48:29+0100 nas monit[2521]: 'collectd' failed to start (exit status 0) -- no output
2017-03-08T11:49:00+0100 nas monit[2521]: 'collectd' process is not running
2017-03-08T11:49:00+0100 nas monit[2521]: 'collectd' trying to restart
2017-03-08T11:49:00+0100 nas monit[2521]: 'collectd' start: '/bin/systemctl start collectd'
2017-03-08T11:49:29+0100 nas smbd[2701]: [2017/03/08 11:49:29.424774,  2] ../source3/smbd/server.c:443(remove_child_pid)
2017-03-08T11:49:29+0100 nas smbd[2701]:   Could not find child 3068 -- ignoring
2017-03-08T11:49:30+0100 nas monit[2521]: 'collectd' failed to start (exit status 0) -- no output
2017-03-08T11:50:00+0100 nas monit[2521]: 'collectd' process is not running
2017-03-08T11:50:00+0100 nas monit[2521]: 'collectd' trying to restart
2017-03-08T11:50:00+0100 nas monit[2521]: 'collectd' start: '/bin/systemctl start collectd'
2017-03-08T11:50:16+0100 nas openmediavault-webgui[3077]: Authorized login from 10.1.1.70 [username=admin, user-agent=Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36]
2017-03-08T11:50:28+0100 nas smbd[3120]: [2017/03/08 11:50:28.047805,  1] ../lib/param/loadparm.c:1638(lpcfg_do_global_parameter)
2017-03-08T11:50:28+0100 nas smbd[3120]:   WARNING: The "null passwords" option is deprecated
2017-03-08T11:50:29+0100 nas smbd[2701]: [2017/03/08 11:50:29.427590,  2] ../source3/smbd/server.c:443(remove_child_pid)
2017-03-08T11:50:29+0100 nas smbd[2701]:   Could not find child 3122 -- ignoring
2017-03-08T11:50:30+0100 nas monit[2521]: 'collectd' failed to start (exit status 0) -- no output

Alles anzeigen

And the syslog (part relevant to collectd):

Code

Mar  8 11:45:28 nas collectd[2371]: plugin_load: plugin "nut" successfully loaded.
Mar  8 11:45:28 nas collectd[2371]: plugin_load: plugin "sensors" successfully loaded.
Mar  8 11:45:28 nas collectd[2570]: plugin_load: plugin "syslog" successfully loaded.
Mar  8 11:45:28 nas collectd[2570]: plugin_load: plugin "rrdcached" successfully loaded.
Mar  8 11:45:28 nas collectd[2570]: plugin_load: plugin "unixsock" successfully loaded.
Mar  8 11:45:28 nas collectd[2570]: plugin_load: plugin "cpu" successfully loaded.
Mar  8 11:45:28 nas collectd[2570]: plugin_load: plugin "df" successfully loaded.
Mar  8 11:45:28 nas collectd[2570]: plugin_load: plugin "interface" successfully loaded.
Mar  8 11:45:28 nas collectd[2570]: plugin_load: plugin "load" successfully loaded.
Mar  8 11:45:28 nas collectd[2570]: plugin_load: plugin "memory" successfully loaded.
Mar  8 11:45:28 nas collectd[2570]: plugin_load: plugin "nut" successfully loaded.
Mar  8 11:45:28 nas collectd[2570]: plugin_load: plugin "sensors" successfully loaded.
Mar  8 11:45:28 nas collectd[2570]: Systemd detected, trying to signal readyness.
Mar  8 11:45:28 nas collectd[2570]: Initialization complete, entering read-loop.
Mar  8 11:45:28 nas collectd[2570]: nut plugin: nut_read_one: upscli_connect (localhost, 3493) failed: Connection failure: Cannot assign requested address
Mar  8 11:45:28 nas collectd[2570]: read-function of plugin `nut' failed. Will suspend it for 20.000 seconds.
Mar  8 11:45:48 nas collectd[2570]: Init SSL without certificate database
Mar  8 11:45:48 nas collectd[2570]: nut plugin: Connection to (localhost, 3493) established.
Mar  8 11:45:58 nas monit[2521]: 'collectd' process is not running
Mar  8 11:45:58 nas monit[2521]: 'collectd' trying to restart
Mar  8 11:45:58 nas monit[2521]: 'collectd' start: '/bin/systemctl start collectd'
Mar  8 11:45:59 nas postfix/smtp[2995]: DFE946455: replace: header Subject: monit alert --  Does not exist collectd: Subject: [nas.necto.loc] monit alert --  Does not exist collectd
Mar  8 11:46:29 nas monit[2521]: 'collectd' failed to start (exit status 0) -- no output
Mar  8 11:46:29 nas postfix/smtp[2995]: 28D3B647A: replace: header Subject: monit alert --  Execution failed collectd: Subject: [nas.necto.loc] monit alert --  Execution failed collectd
Mar  8 11:46:59 nas monit[2521]: 'collectd' process is not running
Mar  8 11:46:59 nas monit[2521]: 'collectd' trying to restart
Mar  8 11:46:59 nas monit[2521]: 'collectd' start: '/bin/systemctl start collectd'
Mar  8 11:47:29 nas monit[2521]: 'collectd' failed to start (exit status 0) -- no output
Mar  8 11:47:59 nas monit[2521]: 'collectd' process is not running
Mar  8 11:47:59 nas monit[2521]: 'collectd' trying to restart
Mar  8 11:47:59 nas monit[2521]: 'collectd' start: '/bin/systemctl start collectd'
Mar  8 11:48:29 nas monit[2521]: 'collectd' failed to start (exit status 0) -- no output
Mar  8 11:49:00 nas monit[2521]: 'collectd' process is not running
Mar  8 11:49:00 nas monit[2521]: 'collectd' trying to restart
Mar  8 11:49:00 nas monit[2521]: 'collectd' start: '/bin/systemctl start collectd'
Mar  8 11:49:30 nas monit[2521]: 'collectd' failed to start (exit status 0) -- no output
Mar  8 11:50:00 nas monit[2521]: 'collectd' process is not running
Mar  8 11:50:00 nas monit[2521]: 'collectd' trying to restart
Mar  8 11:50:00 nas monit[2521]: 'collectd' start: '/bin/systemctl start collectd'

Alles anzeigen

Could it be that nut somehow kills collectd?

I will try to set IP manually & disable nut to see if anything changes

QSx · 8. März 2017

(Doubleposting because of 10K character limit)

I managed to disable UPS/nut - without webui complaining (collectd still fails to start but machine boots normally now)

Any attempted change of System/Network fails with this error:

Code

Error #0:
exception 'OMV\ExecException' with message 'Failed to execute command 'export PATH=/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin:/usr/local/sbin; export LANG=C; systemctl start networking 2>&1' with exit code '1': Job for networking.service failed because the control process exited with error code.
See "systemctl status networking.service" and "journalctl -xe" for details.' in /usr/share/php/openmediavault/system/process.inc:175
Stack trace:
#0 /usr/share/php/openmediavault/system/systemctl.inc(83): OMV\System\Process->execute(Array, 1)
#1 /usr/share/php/openmediavault/system/systemctl.inc(140): OMV\System\SystemCtl->exec('start', NULL, false)
#2 /usr/share/openmediavault/engined/module/networking.inc(44): OMV\System\SystemCtl->start()
#3 /usr/share/openmediavault/engined/rpc/config.inc(189): OMVModuleNetworking->startService()
#4 [internal function]: OMVRpcServiceConfig->applyChanges(Array, Array)
#5 /usr/share/php/openmediavault/rpc/serviceabstract.inc(124): call_user_func_array(Array, Array)
#6 /usr/share/php/openmediavault/rpc/serviceabstract.inc(150): OMV\Rpc\ServiceAbstract->callMethod('applyChanges', Array, Array)
#7 /usr/share/php/openmediavault/rpc/serviceabstract.inc(528): OMV\Rpc\ServiceAbstract->OMV\Rpc\{closure}('/tmp/bgstatusds...', '/tmp/bgoutputQP...')
#8 /usr/share/php/openmediavault/rpc/serviceabstract.inc(151): OMV\Rpc\ServiceAbstract->execBgProc(Object(Closure))
#9 /usr/share/openmediavault/engined/rpc/config.inc(208): OMV\Rpc\ServiceAbstract->callMethodBg('applyChanges', Array, Array)
#10 [internal function]: OMVRpcServiceConfig->applyChangesBg(Array, Array)
#11 /usr/share/php/openmediavault/rpc/serviceabstract.inc(124): call_user_func_array(Array, Array)
#12 /usr/share/php/openmediavault/rpc/rpc.inc(86): OMV\Rpc\ServiceAbstract->callMethod('applyChangesBg', Array, Array)
#13 /usr/sbin/omv-engined(536): OMV\Rpc\Rpc::call('Config', 'applyChangesBg', Array, Array, 1)
#14 {main}

Alles anzeigen

UPDATE:

I enabled nut again / network remains stuck at DHCP (still can't change it due to aforementioned error) - I am greeted by similar (monit) error this time:

Code

Error #0:
exception 'OMV\ExecException' with message 'Failed to execute command 'export PATH=/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin:/usr/local/sbin; export LANG=C; monit summary 2>&1' with exit code '1': Cannot create socket to [localhost]:2812 -- Connection refused' in /usr/share/php/openmediavault/system/process.inc:175
Stack trace:
#0 /usr/share/php/openmediavault/system/monit.inc(142): OMV\System\Process->execute(Array)
#1 /usr/share/php/openmediavault/system/monit.inc(171): OMV\System\Monit->status()
#2 /usr/share/openmediavault/engined/module/nut.inc(105): OMV\System\Monit->isRunning()
#3 /usr/share/openmediavault/engined/rpc/services.inc(56): OMVModuleNetworkUPSTools->getStatus()
#4 [internal function]: OMVRpcServiceServices->getStatus(Array, Array)
#5 /usr/share/php/openmediavault/rpc/serviceabstract.inc(124): call_user_func_array(Array, Array)
#6 /usr/share/php/openmediavault/rpc/rpc.inc(86): OMV\Rpc\ServiceAbstract->callMethod('getStatus', Array, Array)
#7 /usr/sbin/omv-engined(536): OMV\Rpc\Rpc::call('Services', 'getStatus', Array, Array, 1)
#8 {main}

Alles anzeigen

ryecoaaron · 8. März 2017

I will check more systems but I'm not seeing this on my test system.

iddqd · 8. März 2017

Zitat von ryecoaaron

I will check more systems but I'm not seeing this on my test system.

Same here, my OMV3.0 box updated without any problem.

QSx · 8. März 2017

Well, still got trouble here - I think the latest kernel is the culprit or something that has to do with my NIC drivers

Since eth2 error keep appearing in log i tried omv-firstaid and then manually setting the network

Again it failed - i got this error (if it helps)

Code

root@nas:~# systemctl status networking.service
● networking.service - Raise network interfaces
   Loaded: loaded (/lib/systemd/system/networking.service; enabled; vendor preset: enabled)
  Drop-In: /run/systemd/generator/networking.service.d
           └─50-insserv.conf-$network.conf
   Active: failed (Result: exit-code) since Wed 2017-03-08 21:19:49 CET; 20s ago
     Docs: man:interfaces(5)
 Main PID: 4276 (code=exited, status=1/FAILURE)


Mar 08 21:19:49 nas systemd[1]: Starting Raise network interfaces...
Mar 08 21:19:49 nas ifup[4276]: RTNETLINK answers: File exists
Mar 08 21:19:49 nas ifup[4276]: Failed to bring up eth2.
Mar 08 21:19:49 nas systemd[1]: networking.service: Main process exited, code=exited, status=1/FAILURE
Mar 08 21:19:49 nas systemd[1]: Failed to start Raise network interfaces.
Mar 08 21:19:49 nas systemd[1]: networking.service: Unit entered failed state.
Mar 08 21:19:49 nas systemd[1]: networking.service: Failed with result 'exit-code'.

Alles anzeigen

At this point, I'm considering rolling back on previous kernel (is it possible) or slapping another NIC in that machine until whatever got borked gets fixed...

For starters, how would I roll back on today update? Booting old kernel from bootmenu only hangs at "Loading folder2ram systemd service..."

UPDATE: Okay, I disabled onboard chip and slapped on PCI NIC - same crap... any ideas boys?

SimonM · 9. März 2017

"systemctl status networking.service" and "journalctl -xe" results ?

QSx · 9. März 2017

Too late for that - I went with complete system reinstall - now proceeding with setup - I'll report here if problem reappears

b1azk0 · 11. März 2017

QSx did you find any solution?
I'm on a 3rd todays clean install myself and each time network interfaces are blanked

I already tried hints posted for earlier OVM versions but with no luck at all

QSx · 14. März 2017

Negative,

I went with completely fresh install - it's been working fine since (same hardware, same install, same plugins) - no idea what went wrong

Jetzt mitmachen!