Connection Problems between MDM/ERA and Mobile Device

[FHolzer 0]

Hi,

 

I Installed MDMCore on an Linux Server (Centos 6)

 

From Log (IP Adresses and FQDNs disguised)

2016-04-11 18:07:14 I [1] --------------------------------------------------------------------------------
2016-04-11 18:07:14 I [1] MDMCore version: 6.3.110.0
2016-04-11 18:07:14 I [1] Running MDMCore...
2016-04-11 18:07:14 I [1] Loading ESET modules from /var/opt/eset/RemoteAdministrator/MDMCore/Modules/
2016-04-11 18:07:14 I [1] CE2 module initialization
2016-04-11 18:07:15 I [1] Config: server connection: "10.0.x.x", port 2222
2016-04-11 18:07:15 I [1] Config: host: "mxx.xxxxxx.com", port 9981, enrollment port 9980
2016-04-11 18:07:15 I [1] Setting log level from CE to warning
2016-04-11 18:07:15 W [1] Cannot parse APNS cert, iOS enrollment and push notifications will not work
2016-04-11 18:07:18 I [1] Logging to directory /var/log/eset/RemoteAdministrator/MDMCore/Proxy/

i added a Enrollment URL and added a new Device (with IMEI)

Worked Fine.

Enrollment URL is Reachable via Android Device.

 

in ERA the "Last seen Status" updates  - so Device is Communicating ?

 

BUT - i cant Activate the Product via a Task.

For Testing Purpose i activated it manually - but i cant start any other task then either.

 

The loggin is also confusing.

Some things are logged to

/var/log/eset/RemoteAdministrator/MDMCore/trace.log

 

Some other things to

/var/log/eset/RemoteAdministrator/MDMCore/Proxy/trace.log

 

Also, the Timestamp is wrong (2 hours behind) - where can i adjust this ?

(OS Time is right)

 

The Only thing that pops up sometimes is :

2016-04-15 11:57:26 E [7] Uncaught exception: Net Exception, NodSsl returned an error 200. Peer

But absolutly Random - not when i have triggered a Task.
 

Edited April 19, 2016 by FHolzer

[FHolzer 0]

Oh - i forgot something.

On the Same Host Eset Mail Security is installed.

 

So basically i installed Eset Mail Security, the Agent and then MDMCore.

 

Dont know if this can produce an error.

---------

 

Also in "/var/log/eset/RemoteAdministrator/MDMCore/status.html"

everything is Green/OK with current Times. looks good.

 

Same goes for the Agent.

Edited April 19, 2016 by FHolzer

[FHolzer 0]

Turned Loglevel to "Trace" and found this:

 

Mobile Client Connects to MDM:

/var/log/eset/RemoteAdministrator/Agent/trace.log

2016-04-19 17:25:46 Information: CReplicationModule [Thread 7f5e635fe700]: CReplicationManager: Success of scenario (type=Regular, task_id='00000000-0000-0000-7005-000000000001', link='Automatic replication (REGULAR)' (00000000-0000-0000-7007-000000000001), remote_peer=host: "srvfile01" port: 2222, remote_peer_type=3, remote_peer_id=acf59e7a-7e2d-48d0-ba53-bd6489a3fd0d, remote_realm_id=acf59e7a-7e2d-48d0-ba53-bd6489a3fd0d)
2016-04-19 17:25:46 Information: CReplicationModule [Thread 7f5e635fe700]: CReplicationManager: Closing network connection
2016-04-19 17:25:46 Information: NetworkModule [Thread 7f5e92bfd700]: Forcibly closing sessionId:129, isClosing:0
2016-04-19 17:25:46 Information: NetworkModule [Thread 7f5e92bfd700]: Removing session 129
2016-04-19 17:25:46 Information: NetworkModule [Thread 7f5e92bfd700]: Closing connection , session id:129
2016-04-19 17:25:47 Debug: ERAG1ClientConnector [Thread 7f5e4216e700]: <STATUS_LOG_SENDER> New action log type: 'waitingForConnectionTimeout', status: 'ok'
2016-04-19 17:25:47 Information: CMDMCoreConnectorModule [Thread 7f5e4ffff700]: Device 49b3fc1d-ffb8-4c92-a293-5e48452ab8e9 has connected to MDMCore
2016-04-19 17:25:47 Information: CMDMCoreConnectorModule [Thread 7f5e4ffff700]: Published ComputerConnectedEvent for UUID 49b3fc1d-ffb8-4c92-a293-5e48452ab8e9
2016-04-19 17:25:47 Information: CMDMCoreConnectorModule [Thread 7f5e4ffff700]: Device 49b3fc1d-ffb8-4c92-a293-5e48452ab8e9 has connected to MDMCore
2016-04-19 17:25:47 Information: CMDMCoreConnectorModule [Thread 7f5e4ffff700]: Published ComputerConnectedEvent for UUID 49b3fc1d-ffb8-4c92-a293-5e48452ab8e9

Same time in:

/var/log/eset/RemoteAdministrator/MDMCore/trace.log:

2016-04-19 17:25:47 D [7] HTTP request for URL /mdm , port 9981, from IP [::ffff:178.165.130.136]:45204
2016-04-19 17:25:47 I [7] Request from [::ffff:178.165.130.136]:45204 for "/mdm"
2016-04-19 17:25:47 D [7]   Parsing XML
2016-04-19 17:25:47 T [7] Entering isPendingDeviceCert(864826028238601)
2016-04-19 17:25:47 T [7] Entering FormatSql(SELECT PubKeyData FROM PendingDevice WHERE DeviceID=<?>)
2016-04-19 17:25:47 T [7] Leaving FormatSql
2016-04-19 17:25:47 T [7] Leaving isPendingDeviceCert
2016-04-19 17:25:47 T [7] Entering CheckConnectingDevice(864826028238601)
2016-04-19 17:25:47 T [7] Entering IsDeviceCert(864826028238601)
2016-04-19 17:25:47 T [7] Entering FormatSql(SELECT PubKeyData FROM Device WHERE DeviceID=<?>)
2016-04-19 17:25:47 T [7] Leaving FormatSql
2016-04-19 17:25:47 T [7] Leaving IsDeviceCert
2016-04-19 17:25:47 T [7] Entering SetDeviceStatus(864826028238601)
2016-04-19 17:25:47 T [7] Entering GetAgentUUIDForDeviceID(864826028238601)
2016-04-19 17:25:47 T [7] Entering FormatSql(SELECT AgentUuid FROM Device WHERE DeviceID=<?>)
2016-04-19 17:25:47 T [7] Leaving FormatSql
2016-04-19 17:25:47 T [7] Leaving GetAgentUUIDForDeviceID
2016-04-19 17:25:47 T [7] Entering StartTransaction
2016-04-19 17:25:47 T [7] Leaving StartTransaction
2016-04-19 17:25:47 T [7] Entering FormatSql(SELECT Status, DeviceID FROM Device WHERE DeviceID=<?>)
2016-04-19 17:25:47 T [7] Leaving FormatSql
2016-04-19 17:25:47 T [7] Entering FormatSql(UPDATE Device SET LastOnlineTime=? WHERE DeviceID=<?>)
2016-04-19 17:25:47 T [7] Leaving FormatSql
2016-04-19 17:25:47 T [7] Entering Commit
2016-04-19 17:25:47 T [7] Leaving Commit
2016-04-19 17:25:47 T [7] Leaving SetDeviceStatus
2016-04-19 17:25:47 T [7] Leaving CheckConnectingDevice
2016-04-19 17:25:47 D [7]   Status is "Idle", CommandUUID is not present.
2016-04-19 17:25:47 T [7] Entering isDevicePending(864826028238601)
2016-04-19 17:25:47 T [7] Entering FormatSql(SELECT COUNT(*) FROM Device WHERE DeviceID=<?>)
2016-04-19 17:25:47 T [7] Leaving FormatSql
2016-04-19 17:25:47 T [7] Leaving isDevicePending
2016-04-19 17:25:47 T [7] Entering GetDeviceKind(864826028238601)
2016-04-19 17:25:47 T [7] Entering FormatSql(SELECT Kind, DeviceID FROM Device WHERE DeviceID=<?>)
2016-04-19 17:25:47 T [7] Leaving FormatSql
2016-04-19 17:25:47 T [7] Leaving GetDeviceKind
2016-04-19 17:25:47 T [7] Entering GetNextCommandForDevice(864826028238601)
2016-04-19 17:25:47 T [7] Entering SetDeviceStatus(864826028238601)
2016-04-19 17:25:47 T [7] Entering GetAgentUUIDForDeviceID(864826028238601)
2016-04-19 17:25:47 T [7] Entering FormatSql(SELECT AgentUuid FROM Device WHERE DeviceID=<?>)
2016-04-19 17:25:47 T [7] Leaving FormatSql
2016-04-19 17:25:47 T [7] Leaving GetAgentUUIDForDeviceID
2016-04-19 17:25:47 T [7] Entering StartTransaction
2016-04-19 17:25:47 T [7] Leaving StartTransaction
2016-04-19 17:25:47 T [7] Entering FormatSql(SELECT Status, DeviceID FROM Device WHERE DeviceID=<?>)
2016-04-19 17:25:47 T [7] Leaving FormatSql
2016-04-19 17:25:47 T [7] Entering FormatSql(UPDATE Device SET LastOnlineTime=? WHERE DeviceID=<?>)
2016-04-19 17:25:47 T [7] Leaving FormatSql
2016-04-19 17:25:47 T [7] Entering Commit
2016-04-19 17:25:47 T [7] Leaving Commit
2016-04-19 17:25:47 T [7] Leaving SetDeviceStatus
2016-04-19 17:25:47 T [7] Entering GetOneCommandForDevice(864826028238601)
2016-04-19 17:25:47 T [7] Entering FormatSql(SELECT CommandID, CommandXML FROM Command WHERE ((DeviceID=<?>) AND (Status=?)))
2016-04-19 17:25:47 T [7] Leaving FormatSql
2016-04-19 17:25:47 T [7] Leaving GetOneCommandForDevice
2016-04-19 17:25:47 T [7] Leaving GetNextCommandForDevice
2016-04-19 17:25:47 D [7]   Got no command for this device
2016-04-19 17:25:47 D [7]   Sending XML reply
2016-04-19 17:25:47 D [7] finished processing
2016-04-19 17:25:47 D [7] handleRequestImpl took 57428 us (0.057428 sec)
2016-04-19 17:25:51 T [5] Entering resendPushNotifications
2016-04-19 17:25:51 T [5] Entering StartTransaction
2016-04-19 17:25:51 T [5] Leaving StartTransaction
2016-04-19 17:25:51 T [5] Leaving resendPushNotifications
2016-04-19 17:25:58 D [15] Multiagent for 49b3fc1d-ffb8-4c92-a293-5e48452ab8e9 stopped.
2016-04-19 17:25:58 D [15] Marking agent 49b3fc1d-ffb8-4c92-a293-5e48452ab8e9 as non-scheduled

Nothing relevant - or @ same time here:

/var/log/eset/RemoteAdministrator/MDMCore/Proxy/trace.log:

016-04-19 17:25:41 Debug: CReplicationModule [Thread 7f71175fe700]: CStepProcessor: Creating local step DataLogsRegular
2016-04-19 17:25:41 Debug: CReplicationModule [Thread 7f71175fe700]: CStepProcessor: Invoking local step DataLogsRegular
2016-04-19 17:25:42 Debug: CReplicationModule [Thread 7f711f5fe700]: CStepTxLogsRegular: Initialized with data limit: 104857600 bytes
2016-04-19 17:25:42 Debug: CReplicationModule [Thread 7f711f5fe700]: CStepTxLogsRegular: Sending network connection statistics request
2016-04-19 17:25:42 Debug: CReplicationModule [Thread 7f711d7fb700]: CStepTxLogsRegular: Received network statistics (QoS)
2016-04-19 17:25:42 Debug: CReplicationModule [Thread 7f711d7fb700]: CStepTxLogsRegular: Transferring logs
2016-04-19 17:25:42 Debug: CReplicationModule [Thread 7f711d7fb700]: CStepTxLogsRegular: No logs are ready to be transferred
2016-04-19 17:25:42 Debug: CReplicationModule [Thread 7f711d7fb700]: CStepTxLogsRegular: Sending StepEnd with end status: OK
2016-04-19 17:25:42 Debug: CReplicationModule [Thread 7f711ebfd700]: CStepTx: Remote peer confirmed successful end of step 'DataLogsRegular'
2016-04-19 17:25:42 Debug: CReplicationModule [Thread 7f711ebfd700]: CStepProcessor: Current step is finished -> checking whether to invoke next step
2016-04-19 17:25:42 Debug: CReplicationModule [Thread 7f711ebfd700]: CStepProcessor: There is no next step to be invoked -> scenario is successfully finished
2016-04-19 17:25:42 Information: CReplicationModule [Thread 7f711ebfd700]: CReplicationManager: Success of scenario (type=Regular, task_id='00000000-0000-0000-7005-000000000004', link='Automatic replication (REGULAR)' (00000000-0000-0000-7007-000000000001), remote_peer=host: "10.0.100.21" port: 2222, remote_peer_type=3, remote_peer_id=acf59e7a-7e2d-48d0-ba53-bd6489a3fd0d, remote_realm_id=acf59e7a-7e2d-48d0-ba53-bd6489a3fd0d)
2016-04-19 17:25:42 Information: CMultiProxyToMultiAgentConnectorModule [Thread 7f7116bfd700]: Processing functionality product status log
2016-04-19 17:25:42 Debug: CMultiProxyToMultiAgentConnectorModule [Thread 7f7116bfd700]: Calling functionality product status log callback
2016-04-19 17:25:42 Information: CReplicationModule [Thread 7f711ebfd700]: CReplicationManager: Closing network connection
2016-04-19 17:25:42 Information: NetworkModule [Thread 7f7127fff700]: Forcibly closing sessionId:37, isClosing:0
2016-04-19 17:25:42 Information: NetworkModule [Thread 7f7127fff700]: Removing session 37
2016-04-19 17:25:42 Information: NetworkModule [Thread 7f7127fff700]: Closing connection , session id:37
2016-04-19 17:26:11 Debug: SchedulerModule [Thread 7f712e8fd700]: CTimeScheduler: Invoking TimerHandler id: 2
2016-04-19 17:26:11 Debug: SchedulerModule [Thread 7f712e8fd700]: CTimeScheduler: RegisterEventWithTimer: next occurance of id: 2 at: 2016-Apr-19 17:26:41
2016-04-19 17:26:11 Debug: SchedulerModule [Thread 7f712e8fd700]: CTimeScheduler: Finished invoking TimerHandler id: 2
2016-04-19 17:26:11 Debug: SchedulerModule [Thread 7f712f2fe700]: CTimeScheduler: TimeObserverMain: going to sleep for 3600 seconds
2016-04-19 17:26:11 Information: CReplicationModule [Thread 7f710ebfd700]: CReplicationManager: Processing client replication task message
2016-04-19 17:26:11 Information: CReplicationModule [Thread 7f710ebfd700]: CReplicationManager: Initiating replication connection to 'host: "10.0.100.21" port: 2222' (scenario: Regular, data limit: 102400KB)
2016-04-19 17:26:11 Information: NetworkModule [Thread 7f710e1fc700]: Received message: CreateConnectionRequest
2016-04-19 17:26:11 Information: NetworkModule [Thread 7f7127fff700]: Attempting to connect to endpoint: 10.0.100.21
2016-04-19 17:26:11 Information: NetworkModule [Thread 7f7127fff700]: Socket connected.
2016-04-19 17:26:11 Information: NetworkModule [Thread 7f7127fff700]: Socket connection (isClientConnection:1) established for id 38
2016-04-19 17:26:11 Information: NetworkModule [Thread 7f7127fff700]: Sending: VerifyUserRequest
2016-04-19 17:26:11 Information: CProxySecurityModule [Thread 7f710d7fb700]: Verifying certificated user from host 10.0.100.21
2016-04-19 17:26:11 Information: CProxySecurityModule [Thread 7f710d7fb700]: Creating replication server user
2016-04-19 17:26:11 Information: NetworkModule [Thread 7f7127fff700]: Receiving: VerifyUserResponse
2016-04-19 17:26:11 Information: CReplicationModule [Thread 7f710ebfd700]: CReplicationManager: Successfully opened connection to 'host: "" port: 2222' (remote product type: 3)
2016-04-19 17:26:11 Information: CReplicationModule [Thread 7f710ebfd700]: CReplicationManager: Sending replication initialization message to replication slave
2016-04-19 17:26:11 Information: CReplicationModule [Thread 7f711ffff700]: CStepProcessor: Replication slave identified as: acf59e7a-7e2d-48d0-ba53-bd6489a3fd0d [realm: acf59e7a-7e2d-48d0-ba53-bd6489a3fd0d] (product type: 3, protocol version: 6200)
2016-04-19 17:26:11 Debug: CReplicationModule [Thread 7f711ffff700]: CStepProcessor: ValidateReplicationRequestVersion: Validating protocol version of peer 'acf59e7a-7e2d-48d0-ba53-bd6489a3fd0d' (remote version: 6200, local version: 6200, is slave: 0)
2016-04-19 17:26:11 Debug: CReplicationModule [Thread 7f711ffff700]: CStepProcessor: Creating remote step MetadataStaticObjects
2016-04-19 17:26:11 Debug: CReplicationModule [Thread 7f711ffff700]: CStepProcessor: Invoking remote step MetadataStaticObjects
2016-04-19 17:26:11 Debug: CReplicationModule [Thread 7f7117fff700]: CStepRx: Remote peer signalized start of step 'MetadataStaticObjects'
2016-04-19 17:26:11 Debug: CReplicationModule [Thread 7f711e1fc700]: CStepRxStaticObjectsMetadata: Received remote static objects metadata ({acf59e7a-7e2d-48d0-ba53-bd6489a3fd0d,1336})

also

the error i posted in First Post seems to be from the Webserver Connect.

2016-04-19 16:01:41 D [69] HTTP request for URL / , port 9980, from IP [::ffff:77.119.128.xx]:32070
2016-04-19 16:01:41 D [69] Sending index.html
2016-04-19 16:01:41 E [70] Uncaught exception: Net Exception, NodSsl returned an error 200. Peer [::ffff:77.119.128.xx:55869, local [::ffff:10.0.xx.7]:9980
2016-04-19 16:01:41 E [69] Uncaught exception: Net Exception, NodSsl returned an error 200. Peer [::ffff:77.119.128.xx]:41984, local [::ffff:10.0.xx.7]:9980

It shows up in the log right after i visit https://mdm-hostname:9980

 

But i cant find an "real" Error why the Task doesnt work.

Edited April 19, 2016 by FHolzer

[FHolzer 0]

any ideas ?

 

Are the Logs ok ?

 

ist the "WHERE DeviceID=<?>)" ok ? im just curious about the "?"

at this point i cant resell this product and the Appliance is no option

[madmaxoft 3]

Hello,

the logs don't seem to indicate any problem.

 

In the /var/log/eset/RemoteAdministrator/MDMCore/trace.log file, is there any mention of the string "New command from AgentConnector"? It indicates when the task from ERA webconsole reaches MDMCore to be relayed to the mobile, and is present in up to "Information" verbosity.

 

The log times are in UTC, hence the offset.

 

The "<?>" in the SQL query is the parameter substitution symbol, the SQL engine binds parameters using this placeholder (and thus avoids SQL injection).

[FHolzer 0]

Hello Madmaxoft,

 

Thanks for you detailed reply.

Sadly - no - there are no "new command from AgentConnector" Logs.

 

The only things i find about "command" are

2016-04-24 18:18:36 D [467]   Got no command for this device

or

2016-04-25 01:00:06 D [549] There are commands (1) waiting for the device 864826028238601, sending a push notification.

full

2016-04-25 01:00:06 D [549] There are commands (1) waiting for the device 864826028238601, sending a push notification.
2016-04-25 01:00:06 T [3] Entering GetDevice(864826028238601)
2016-04-25 01:00:06 T [549] Leaving UpdateDeviceTokens
2016-04-25 01:00:06 D [549]   Sending XML reply
2016-04-25 01:00:06 D [549] finished processing
2016-04-25 01:00:06 T [3] Entering FormatSql(SELECT Kind, PushToken, PushMagic, AppPushToken, Status, DeviceID FROM Device WHERE DeviceID=<?>)
2016-04-25 01:00:06 T [3] Leaving FormatSql
2016-04-25 01:00:06 D [549] handleRequestImpl took 59387 us (0.059387 sec)
2016-04-25 01:00:06 T [3] Leaving GetDevice
2016-04-25 01:00:06 I [3] GCM Notification send. Got response "{"multicast_id":7970885299161554844,"success":1,"failure":0,"canonical_ids":0,"results":[{"message_id":"0:1461546007046477%e24a38d9f9fd7ecd"}]}".

the follow up is posted in #3

Edited April 25, 2016 by FHolzer

[FHolzer 0]

no help further ?

I mean it doesnt work and i cant find an error - could it be the device ?

[MichalJ 434]

It's not the device. The task hasn't arrived to MDMCore from the ERA server. I suggest you try to create another activation task, and if it doesn't work, contact ESET support and have the full log files (especially /var/log/eset/RemoteAdministrator/MDMCore/trace.* and /var/log/eset/RemoteAdministrator/MDMCore/Proxy/trace.*) ready for them.