[9.171][NOTREPROD] SUM continually getting Connection to device has been lost

Hi Mark,
2 UTMs on 9.171 and 1 on 9.106 all reporting to the SUM without a problem. I have logged into the 2 running 9.171 and looked at the SUM connection, while a little longer than expected still connected okay.

You might be having the PPPoE issue on your older UTMs?

Ian

Hi All
Since moving to 9.1 I'm continually getting to below message from externally connected devices to my SUM.
"Connection to device has been lost (ping timeout)".
My SUM device is connected through my firewall with a NAT rule.

My old 9.0 is a Virtual and the new 9.1 is a copy of the old Virtual with a import of the old configuration and patched to 9.171. So the only things changed is within 9.1.

I can turn on the old 9.0 (and 9.1 off) and all is fine.

Mark

Hi Mark,
you said that you copied the systems within VMWare. Can you please check if both systems have the same system_id? (please execute on your UTMs: cc get settings system_id)

UTMs are identified by their system_id therefore this needs to be unique.

Hi Snowcrash
I have reinstalled again from the ISO and (not exact sure on order, as this was the other day) Installed Backup and Lastest update 9.171.
With Uplink monitoring and Balancing Off.
I'm getting 18 failures ea 3 Hrs period.
The connection to device *** (***.***.***.***) has been lost (ping timeout).
Fine in previous version.

I'm using Cable with 100Mb/2Mb

Mark

 Can you please check if both systems have the same system_id? (please execute on your UTMs: cc get settings system_id)

Hi Mark,

Can you please provide this output, so we can investigate further?
Thanks!
Bianca

Hi Bianca
Here is a copy of the out put from the two systems.
The numbers are the same I assume this is because I have used the same Sophos "Backup File" to start from. Because the builds are from different media ISO versions.

Using username "root".
Authenticating with public key "fmaster-root"
Passphrase for key "fmaster-root":
Last login: Tue Nov 26 12:39:43 2013 from 172.16.20.8


Sophos UTM
(C) Copyrights by Sophos Ltd and by others 2000-2013.
For more copyright information look at /doc/astaro-license.txt
or http://www.astaro.com/doc/astaro-license.txt

NOTE: Any modifications done by root will void your support.
      Please use WebAdmin for any configuration changes.

fmaster:/root # cc get settings system_id
082f2897-ffa0-3ddd-bac6-05a9f9297259


Using username "root".
Authenticating with public key "fmaster-root"
Passphrase for key "fmaster-root":
Last login: Tue Nov 26 12:34:34 2013 from 172.16.20.8


Sophos UTM
(C) Copyrights by Sophos Ltd and by others 2000-2013.
For more copyright information look at /doc/astaro-license.txt
or http://www.astaro.com/doc/astaro-license.txt

NOTE: Any modifications done by root will void your support.
      Please use WebAdmin for any configuration changes.

fmaster:/root # cc get settings system_id
082f2897-ffa0-3ddd-bac6-05a9f9297259
fmaster:/root #

Hi Bianca
With 9.171 running I've got 81 emails in 22hrs saying 
[INFO-901] Device went offline Date Sun, 01 Dec 2013 11:27:10 +1100
and then 
[INFO-903] Device came online Date Sun, 01 Dec 2013 11:27:11 +1100

With 9.0 and the same config I don't get these.
SUM output
2013:12:01-11:27:10 sum accd: 176533603 [0xe03f6b70] WARN  server.device.DeviceSession null - DeviceSession::clear() IO error during recv [device;guid:16F30520-9D8B-11E2-BE8F-C4D86F7D7947;ip:115.70.206.10;name[:D]ingo]
2013:12:01-11:27:10 sum accd: 176533609 [0xe03f6b70] INFO  server.device.DeviceCache null - DeviceCache::logout() device ... [device;guid:16F30520-9D8B-11E2-BE8F-C4D86F7D7947;ip:115.70.206.10;name[:D]ingo]
2013:12:01-13:23:41 sum accd: 183524588 [0xf2f28b70] WARN  server.device.CheckPingAction null - 2 missed ping(s) device 16F30520-9D8B-11E2-BE8F-C4D86F7D7947
2013:12:01-13:24:11 sum accd: 183554588 [0xf2527b70] WARN  server.device.CheckPingAction null - 3 missed ping(s) device 16F30520-9D8B-11E2-BE8F-C4D86F7D7947
2013:12:01-13:24:11 sum accd: 183554588 [0xf2527b70] ERROR server.device.CheckPingAction null - device [device;guid:16F30520-9D8B-11E2-BE8F-C4D86F7D7947;ip:115.70.206.10;name[:D]ingo] missed 3 pings => disconnecting
2013:12:01-13:24:11 sum accd: 183554638 [0xe03f6b70] WARN  server.device.DeviceSession null - DeviceSession::clear() IO error during recv [device;guid:16F30520-9D8B-11E2-BE8F-C4D86F7D7947;ip:115.70.206.10;name[:D]ingo]
2013:12:01-13:24:11 sum accd: 183554706 [0xf2527b70] INFO  server.device.DeviceCache null - DeviceCache::logout() device ... [device;guid:16F30520-9D8B-11E2-BE8F-C4D86F7D7947;ip:115.70.206.10;name[:D]ingo]
2013:12:01-13:30:16 sum accd: 183919587 [0xe2bfbb70] WARN  server.device.CheckPingAction null - 2 missed ping(s) device 16F30520-9D8B-11E2-BE8F-C4D86F7D7947
2013:12:01-13:30:46 sum accd: 183949587 [0xead18b70] WARN  server.device.CheckPingAction null - 3 missed ping(s) device 16F30520-9D8B-11E2-BE8F-C4D86F7D7947
2013:12:01-13:30:46 sum accd: 183949587 [0xead18b70] ERROR server.device.CheckPingAction null - device [device;guid:16F30520-9D8B-11E2-BE8F-C4D86F7D7947;ip:115.70.206.10;name[:D]ingo] missed 3 pings => disconnecting
2013:12:01-13:30:46 sum accd: 183949593 [0xe03f6b70] WARN  server.device.DeviceSession null - DeviceSession::clear() IO error during recv [device;guid:16F30520-9D8B-11E2-BE8F-C4D86F7D7947;ip:115.70.206.10;name[:D]ingo]
2013:12:01-13:30:46 sum accd: 183949597 [0xead18b70] INFO  server.device.DeviceCache null - DeviceCache::logout() device ... [device;guid:16F30520-9D8B-11E2-BE8F-C4D86F7D7947;ip:115.70.206.10;name[:D]ingo]

External Host Ping test from SUM.

PING ***x.***x.***x.***x (***x.***x.***x.***x) 56(84) bytes of data.

64 bytes from ***x.***x.***x.***x: icmp_seq=1 ttl=50 time=14.9 ms

64 bytes from ***x.***x.***x.***x: icmp_seq=2 ttl=50 time=13.4 ms

64 bytes from ***x.***x.***x.***x: icmp_seq=3 ttl=50 time=13.8 ms

64 bytes from ***x.***x.***x.***x: icmp_seq=4 ttl=50 time=14.2 ms

64 bytes from ***x.***x.***x.***x: icmp_seq=5 ttl=50 time=27.3 ms

Speed Test

Speedtest.net by Ookla - My Results

Hi Mark,

are you trying to connect the two UTMs with the same system_id to the SUM at the
same time?

From what I understood from your first post, you are not. You turned off the 9.0 and only
tried to connect the new 9.1 to the SUM, right?

If so, then it's not a problem that the new UTM has the same system_id. It's a problem
when you try to connect both to the SUM as only one, i.e. the one that connects first,
will be accepted by SUM. Any further UTM with that id won't be accepted.

Regards, Hakan

Hi Mark,

according to the SUMs log file portion your UTM was disconnected by the SUM because
of ping timeouts at:

2013:12:01-11:27:10
2013:12:01-13:24:11
2013:12:01-13:30:46

Could you please check on your UTM what happened at that points in time, e.g. in the
device-agent.log file?

Regards, Hakan

Hi Hakan
I only turn on one or the other VM at no time have the two UTM's been on together (it would cause way to many internal problems).
I have currently turned off notifications for the one external UTM (as mail providers where deeming the amount of email generated as spam).
I will post logs as requested.

Mark

Hi hakan
Below is a copy of log for a number of events.

2013:12:04-01:09:25 dingo device-agent[4907]:   timer2 -> module 1 not executing: denied by role
2013:12:04-01:09:25 dingo device-agent[4907]:   timer2 -> module 2 not executing: denied by role
2013:12:04-01:09:25 dingo device-agent[4907]:   timer2 -> module 3 not executing: denied by role
2013:12:04-01:09:25 dingo device-agent[4907]:   timer2 -> module 4 not executing: denied by role
2013:12:04-01:09:25 dingo device-agent[4907]:   timer2 -> module 5 not executing: denied by role
2013:12:04-01:09:25 dingo device-agent[4907]:   timer2 -> module 6 not executing: denied by role
2013:12:04-01:09:25 dingo device-agent[4907]:   timer2 -> module 7 not executing: denied by role
2013:12:04-01:09:25 dingo device-agent[4907]:   1 is not connected. Trying to connect
2013:12:04-01:09:25 dingo device-agent[4907]:   Updating SUM IP address for path: acc/server1/server
2013:12:04-01:09:25 dingo device-agent[4907]:   [1] Connecting to SUM (ip=***.***.***.***, port=4433).
2013:12:04-01:09:25 dingo device-agent[4907]:   [1] Using SUM SSL connection.
2013:12:04-01:09:25 dingo device-agent[4907]:   [1] We are now connected (ip=***.***.***.***, port=4433).
2013:12:04-01:09:25 dingo device-agent[4907]:   SUM ehlo notification from [1]
2013:12:04-01:09:25 dingo device-agent[4907]:   Setting minimum notify wait for '/etc/sysmond.ph' to 180
2013:12:04-01:09:25 dingo device-agent[4907]:   Setting minimum notify wait for '/etc/selfmon.ph' to 180
2013:12:04-01:09:25 dingo device-agent[4907]:   Setting update interval for availability_ups from 60 to 60
2013:12:04-01:09:25 dingo device-agent[4907]:   Setting update interval for license_subscriptions from 600 to 600
2013:12:04-01:09:25 dingo device-agent[4907]:   Setting update interval for monitoring_vpn from 54 to 54
2013:12:04-01:09:25 dingo device-agent[4907]:   Setting update interval for services from 18 to 18
2013:12:04-01:09:25 dingo device-agent[4907]:   Setting update interval for ip from 12960 to 12960
2013:12:04-01:09:25 dingo device-agent[4907]:   Setting update interval for availability_ha from 60 to 60
2013:12:04-01:09:25 dingo device-agent[4907]:   Setting update interval for license_count from 60 to 60
2013:12:04-01:09:25 dingo device-agent[4907]:   'login successful, welcome to duty'.
2013:12:04-01:09:25 dingo device-agent[4907]:   Login complete for [1].
2013:12:04-01:09:25 dingo device-agent[4907]:   Setting available subscriptions for product 'ASG'
2013:12:04-01:09:25 dingo device-agent[4907]:   Creating Watcher (timer) for 'weekly' -> 14400
2013:12:04-01:09:25 dingo device-agent[4907]:   Canceling previous watcher for interval weekly
2013:12:04-01:09:25 dingo device-agent[4907]:   Creating Watcher (timer) for 'monthly' -> 43200
2013:12:04-01:09:25 dingo device-agent[4907]:   Canceling previous watcher for interval monthly
2013:12:04-01:09:25 dingo device-agent[4907]:   Creating Watcher (timer) for 'yearly' -> 86400
2013:12:04-01:09:25 dingo device-agent[4907]:   Canceling previous watcher for interval yearly
2013:12:04-01:09:25 dingo device-agent[4907]:   Creating Watcher (timer) for 'daily' -> 900
2013:12:04-01:09:25 dingo device-agent[4907]:   Canceling previous watcher for interval daily
2013:12:04-01:09:25 dingo device-agent[4907]:   Done subscribing
2013:12:04-01:09:25 dingo device-agent[4907]:   Updating Location...
2013:12:04-01:10:05 dingo device-agent[4907]:   Reporting 2 changes to accd (inotify: /var/log/reporting/accu/pfilter.accu).
2013:12:04-01:11:09 dingo device-agent[4907]:   Reporting 2 changes to accd (inotify: /etc/up2date/up2date_status).
2013:12:04-01:12:02 dingo device-agent[4907]:   Reporting 16 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-01:15:02 dingo device-agent[4907]:   Reporting 19 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-01:15:04 dingo device-agent[4907]:   Reporting 2 changes to accd (inotify: /var/log/reporting/accu/pfilter.accu).
2013:12:04-01:15:05 dingo device-agent[4907]:   Reporting 2 changes to accd (inotify: /var/log/reporting/accu/ipsevent.accu).
2013:12:04-01:18:03 dingo device-agent[4907]:   Reporting 20 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-01:20:04 dingo device-agent[4907]:   Reporting 2 changes to accd (inotify: /var/log/reporting/accu/pfilter.accu).
2013:12:04-01:21:03 dingo device-agent[4907]:   Reporting 19 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-01:22:55 dingo device-agent[4907]:   [1] Received 0 bytes (eof).
2013:12:04-01:22:55 dingo device-agent[4907]:   SUM disconnect [1]
2013:12:04-01:22:56 dingo device-agent[4907]:   timer2 -> module 1 not executing: denied by role
2013:12:04-01:22:56 dingo device-agent[4907]:   timer2 -> module 2 not executing: denied by role
2013:12:04-01:22:56 dingo device-agent[4907]:   timer2 -> module 3 not executing: denied by role
2013:12:04-01:22:56 dingo device-agent[4907]:   timer2 -> module 4 not executing: denied by role
2013:12:04-01:22:56 dingo device-agent[4907]:   timer2 -> module 5 not executing: denied by role
2013:12:04-01:22:56 dingo device-agent[4907]:   timer2 -> module 6 not executing: denied by role
2013:12:04-01:22:56 dingo device-agent[4907]:   timer2 -> module 7 not executing: denied by role
2013:12:04-01:22:56 dingo device-agent[4907]:   1 is not connected. Trying to connect
2013:12:04-01:22:56 dingo device-agent[4907]:   Updating SUM IP address for path: acc/server1/server
2013:12:04-01:22:56 dingo device-agent[4907]:   [1] Connecting to SUM (ip=***.***.***.***, port=4433).
2013:12:04-01:22:56 dingo device-agent[4907]:   [1] Using SUM SSL connection.
2013:12:04-01:22:56 dingo device-agent[4907]:   [1] We are now connected (ip=***.***.***.***, port=4433).
2013:12:04-01:22:56 dingo device-agent[4907]:   SUM ehlo notification from [1]
2013:12:04-01:22:56 dingo device-agent[4907]:   Setting minimum notify wait for '/etc/sysmond.ph' to 180
2013:12:04-01:22:56 dingo device-agent[4907]:   Setting minimum notify wait for '/etc/selfmon.ph' to 180
2013:12:04-01:22:56 dingo device-agent[4907]:   Setting update interval for availability_ups from 60 to 60
2013:12:04-01:22:56 dingo device-agent[4907]:   Setting update interval for license_subscriptions from 600 to 600
2013:12:04-01:22:56 dingo device-agent[4907]:   Setting update interval for monitoring_vpn from 54 to 54
2013:12:04-01:22:56 dingo device-agent[4907]:   Setting update interval for services from 18 to 18
2013:12:04-01:22:56 dingo device-agent[4907]:   Setting update interval for ip from 12960 to 12960
2013:12:04-01:22:56 dingo device-agent[4907]:   Setting update interval for availability_ha from 60 to 60
2013:12:04-01:22:56 dingo device-agent[4907]:   Setting update interval for license_count from 60 to 60
2013:12:04-01:22:56 dingo device-agent[4907]:   'login successful, welcome to duty'.
2013:12:04-01:22:56 dingo device-agent[4907]:   Login complete for [1].
2013:12:04-01:22:56 dingo device-agent[4907]:   Setting available subscriptions for product 'ASG'
2013:12:04-01:22:56 dingo device-agent[4907]:   Creating Watcher (timer) for 'weekly' -> 14400
2013:12:04-01:22:56 dingo device-agent[4907]:   Canceling previous watcher for interval weekly
2013:12:04-01:22:56 dingo device-agent[4907]:   Creating Watcher (timer) for 'monthly' -> 43200
2013:12:04-01:22:56 dingo device-agent[4907]:   Canceling previous watcher for interval monthly
2013:12:04-01:22:56 dingo device-agent[4907]:   Creating Watcher (timer) for 'yearly' -> 86400
2013:12:04-01:22:56 dingo device-agent[4907]:   Canceling previous watcher for interval yearly
2013:12:04-01:22:56 dingo device-agent[4907]:   Creating Watcher (timer) for 'daily' -> 900
2013:12:04-01:22:56 dingo device-agent[4907]:   Canceling previous watcher for interval daily
2013:12:04-01:22:56 dingo device-agent[4907]:   Done subscribing
2013:12:04-01:22:56 dingo device-agent[4907]:   Updating Location...

Saw this entry further down

2013:12:04-15:59:15 dingo device-agent[4907]:   Reporting 22 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-16:00:04 dingo device-agent[4907]:   Reporting 2 changes to accd (inotify: /var/log/reporting/accu/pfilter.accu).
2013:12:04-16:02:16 dingo device-agent[4907]:   Reporting 22 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-16:05:04 dingo device-agent[4907]:   Reporting 2 changes to accd (inotify: /var/log/reporting/accu/pfilter.accu).
2013:12:04-16:05:16 dingo device-agent[4907]:   Reporting 18 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-16:08:16 dingo device-agent[4907]:   Reporting 20 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-16:10:05 dingo device-agent[4907]:   Reporting 2 changes to accd (inotify: /var/log/reporting/accu/pfilter.accu).
2013:12:04-16:11:16 dingo device-agent[4907]:   Reporting 20 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-16:12:05 dingo device-agent[4907]:   Creating 'daily' reporting data
2013:12:04-16:12:05 dingo device-agent[4907]:   reporting.change': daily
2013:12:04-16:14:16 dingo device-agent[4907]:   Reporting 21 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-16:15:04 dingo device-agent[4907]:   Reporting 2 changes to accd (inotify: /var/log/reporting/accu/pfilter.accu).
2013:12:04-16:17:16 dingo device-agent[4907]:   Reporting 22 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-16:20:04 dingo device-agent[4907]:   Reporting 2 changes to accd (inotify: /var/log/reporting/accu/pfilter.accu).
2013:12:04-16:20:16 dingo device-agent[4907]:   Reporting 17 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-16:23:17 dingo device-agent[4907]:   Reporting 21 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-16:25:04 dingo device-agent[4907]:   Reporting 2 changes to accd (inotify: /var/log/reporting/accu/pfilter.accu).
2013:12:04-16:26:17 dingo device-agent[4907]:   Reporting 22 changes to accd (inotify: /etc/sysmond.ph).
2013:12:04-16:27:05 dingo device-agent[4907]:   Creating 'daily' reporting data
2013:12:04-16:27:05 dingo device-agent[4907]:   reporting.change': daily
2013:12:04-16:28:07 dingo device-agent[4907]:   [1] Write failed after 420000 retries. Could not send data for over 1 Minute.
2013:12:04-16:29:08 dingo device-agent[4907]:   [1] Write failed after 840000 retries. Could not send data for over 2 Minutes.
2013:12:04-16:30:09 dingo device-agent[4907]:   [1] Write failed after 1260000 retries. Could not send data for over 3 Minutes. Giving up.
2013:12:04-16:30:09 dingo device-agent[4907]:   Syswrite has returned an undefined result: "No such file or directory" writing data to socket.
2013:12:04-16:30:09 dingo device-agent[4907]:   out_buffer not empty. flushing...
2013:12:04-16:30:09 dingo device-agent[4907]:   Not reporting inotify: no role
2013:12:04-16:30:09 dingo device-agent[4907]:   Not reporting inotify: no role
2013:12:04-16:30:09 dingo device-agent[4907]:   Not reporting inotify: no role
2013:12:04-16:30:09 dingo device-agent[4907]:   Not reporting inotify: no role
2013:12:04-16:30:09 dingo device-agent[4907]:   Not reporting inotify: no role
2013:12:04-16:30:09 dingo device-agent[4907]:   timer2 -> module 1 not executing: denied by role
2013:12:04-16:30:09 dingo device-agent[4907]:   timer2 -> module 2 not executing: denied by role
2013:12:04-16:30:09 dingo device-agent[4907]:   timer2 -> module 3 not executing: denied by role
2013:12:04-16:30:09 dingo device-agent[4907]:   timer2 -> module 4 not executing: denied by role
2013:12:04-16:30:09 dingo device-agent[4907]:   timer2 -> module 5 not executing: denied by role
2013:12:04-16:30:09 dingo device-agent[4907]:   timer2 -> module 6 not executing: denied by role
2013:12:04-16:30:09 dingo device-agent[4907]:   timer2 -> module 7 not executing: denied by role
2013:12:04-16:30:09 dingo device-agent[4907]:   1 is not connected. Trying to connect
2013:12:04-16:30:09 dingo device-agent[4907]:   Updating SUM IP address for path: acc/server1/server
2013:12:04-16:30:09 dingo device-agent[4907]:   [1] Connecting to SUM (ip=***.***.***.***, port=4433).
2013:12:04-16:30:09 dingo device-agent[4907]:   [1] Using SUM SSL connection.
2013:12:04-16:30:09 dingo device-agent[4907]:   [1] We are now connected (ip=***.***.***.***, port=4433).
2013:12:04-16:30:09 dingo device-agent[4907]:   SUM ehlo notification from [1]
2013:12:04-16:30:09 dingo device-agent[4907]:   Setting minimum notify wait for '/etc/sysmond.ph' to 180
2013:12:04-16:30:09 dingo device-agent[4907]:   Setting minimum notify wait for '/etc/selfmon.ph' to 180
2013:12:04-16:30:09 dingo device-agent[4907]:   Setting update interval for availability_ups from 60 to 60
2013:12:04-16:30:09 dingo device-agent[4907]:   Setting update interval for license_subscriptions from 600 to 600
2013:12:04-16:30:09 dingo device-agent[4907]:   Setting update interval for monitoring_vpn from 54 to 54
2013:12:04-16:30:09 dingo device-agent[4907]:   Setting update interval for services from 18 to 18
2013:12:04-16:30:09 dingo device-agent[4907]:   Setting update interval for ip from 12960 to 12960
2013:12:04-16:30:09 dingo device-agent[4907]:   Setting update interval for availability_ha from 60 to 60
2013:12:04-16:30:09 dingo device-agent[4907]:   Setting update interval for license_count from 60 to 60
2013:12:04-16:30:09 dingo device-agent[4907]:   'login successful, welcome to duty'.
2013:12:04-16:30:09 dingo device-agent[4907]:   Login complete for [1].
2013:12:04-16:30:09 dingo device-agent[4907]:   Setting available subscriptions for product 'ASG'
2013:12:04-16:30:09 dingo device-agent[4907]:   Creating Watcher (timer) for 'weekly' -> 14400
2013:12:04-16:30:09 dingo device-agent[4907]:   Canceling previous watcher for interval weekly
2013:12:04-16:30:09 dingo device-agent[4907]:   Creating Watcher (timer) for 'monthly' -> 43200
2013:12:04-16:30:09 dingo device-agent[4907]:   Canceling previous watcher for interval monthly
2013:12:04-16:30:09 dingo device-agent[4907]:   Creating Watcher (timer) for 'yearly' -> 86400
2013:12:04-16:30:09 dingo device-agent[4907]:   Canceling previous watcher for interval yearly
2013:12:04-16:30:09 dingo device-agent[4907]:   Creating Watcher (timer) for 'daily' -> 900
2013:12:04-16:30:09 dingo device-agent[4907]:   Canceling previous watcher for interval daily
2013:12:04-16:30:09 dingo device-agent[4907]:   Done subscribing
2013:12:04-16:30:09 dingo device-agent[4907]:   Updating Location...
Mark