Optimizers "Already connected"

[hmiyake]

Hello,

Sometimes we see following message in Optimizers log.
In one case the message appears only one time but in other time we see never ending message as following

    2024-12-19 21:02:57 UTC WorkloadManagement/Optimizers NOTICE: Trying to reconnect to WorkloadManagement/OptimizationMind
    2024-12-19 21:02:57 UTC WorkloadManagement/Optimizers INFO: Connect error failed: Already connected
    2024-12-19 21:02:57 UTC WorkloadManagement/Optimizers NOTICE: Failed to reconnect. Sleeping for 1 seconds
    2024-12-19 21:02:58 UTC WorkloadManagement/Optimizers NOTICE: Trying to reconnect to WorkloadManagement/OptimizationMind
    2024-12-19 21:02:58 UTC WorkloadManagement/Optimizers INFO: Connect error failed: Already connected
    2024-12-19 21:02:58 UTC WorkloadManagement/Optimizers NOTICE: Failed to reconnect. Sleeping for 1 seconds 

We need to restart Optimizers in such case.

I wonder how we can avoid the error...now we are running four Optimizers instances in parallel, just installed with different names.

Do we need further configuration to run multiple Optimizers? Or does it indicate necessity of Linux kernel parameters tuning?

[fstagni]

Hi,

• which version of DIRAC are you using?
• When it happens, do you see something interesting the log of the WorkloadManagement/OptimizationMind?

I do not see anything regarding kernel parameters tuning.

[hmiyake]

Sorry I haven't answered...

• Our DIRAC version is 8.0.44.

• No. Oppositely nothing was recorded at that time.

2024-12-19 21:02:25 UTC WorkloadManagement/OptimizationMind NOTICE: Executing action ([::ffff:202.13.203.87]:46462)[hosts:cav09g01.cc.kek.jp] Message/msg_OptimizeJobs(<masked>)
2024-12-19 21:02:25 UTC WorkloadManagement/OptimizationMind INFO: Dispatching job  448503869 to JobPath
2024-12-19 21:02:25 UTC WorkloadManagement/OptimizationMind INFO: Received new job 448503869
2024-12-19 21:02:25 UTC WorkloadManagement/OptimizationMind NOTICE: Returning response ([::ffff:202.13.203.87]:46462)[hosts:cav09g01.cc.kek.jp] (0.00 secs) OK
2024-12-19 21:02:25 UTC WorkloadManagement/OptimizationMind NOTICE: Executing action ([::ffff:202.13.203.85]:53658)[hosts:cav08g01.cc.kek.jp] Message/msg_TaskDone(<masked>)
2024-12-19 21:02:25 UTC WorkloadManagement/OptimizationMind INFO: Saving changes for job  448503869 after WorkloadManagement/JobPath
2024-12-19 21:02:25 UTC WorkloadManagement/OptimizationMind/WorkloadManagement/JobLoggingDB INFO: Adding record for job  448503869: 'status/minor/app=Checking/Scouting/idem' from JobPath
2024-12-19 21:02:25 UTC WorkloadManagement/OptimizationMind/WorkloadManagement/JobLoggingDB INFO: Adding record for job  448503869: 'status/minor/app=Scouting/Waiting for Scout Job Completion/Unknown' from Scouting
2024-12-19 21:02:25 UTC WorkloadManagement/OptimizationMind INFO: Job 448503869: Ended trace execution
2024-12-19 21:02:25 UTC WorkloadManagement/OptimizationMind INFO: Dispatching job 448503869 out of optimization
2024-12-19 21:02:25 UTC WorkloadManagement/OptimizationMind NOTICE: Returning response ([::ffff:202.13.203.85]:53658)[hosts:cav08g01.cc.kek.jp] (0.05 secs) OK
2024-12-19 21:03:12 UTC WorkloadManagement/OptimizationMind NOTICE: Executing action ([::ffff:202.13.203.87]:46462)[hosts:cav09g01.cc.kek.jp] Message/msg_OptimizeJobs(<masked>)
2024-12-19 21:03:12 UTC WorkloadManagement/OptimizationMind INFO: Dispatching job  448664058 to JobPath
2024-12-19 21:03:12 UTC WorkloadManagement/OptimizationMind INFO: Received new job 448664058

I also found different pattern ...

2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1 NOTICE: Reconnected to WorkloadManagement/OptimizationMind
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1 INFO: Closing transport because of error while processing message Already connected
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1 INFO: Closing transport because of error while processing message Already connected
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1/WorkloadManagement/JobPath/JobPath/JID_453605534 INFO: Processing
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1 WARN: Error while receiving message from (202.13.203.85:9175) : Peer closed connection
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1 NOTICE: Trying to reconnect to WorkloadManagement/OptimizationMind
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1/WorkloadManagement/JobPath/JobPath/JID_453605534 INFO: Input data requirement found
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1/WorkloadManagement/JobPath/JobPath/JID_453605534 INFO: Constructed path is JobPath->Scouting->JobSanity->InputData->JobScheduling
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1/WorkloadManagement/JobPath/JobPath/JID_453605534 INFO: Set to Checking/Scouting
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1/WorkloadManagement/JobPath INFO: [JID 453605534] Fast track possible to Scouting
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1 NOTICE: Fast tracking task 453605534 to WorkloadManagement/Scouting
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1/WorkloadManagement/Scouting/Scouting/JID_453605534 INFO: Processing
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1/WorkloadManagement/Scouting/Scouting/JID_453605534 INFO: Getting scoutparams from JobParameters
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1/WorkloadManagement/Scouting/Scouting/JID_453605534 INFO: From AtticJobParameter: {'OK': True, 'Value': {}}
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1/WorkloadManagement/Scouting/Scouting/JID_453605534 INFO: Setting scoutparams (ID:453604224:453604233, Flag:0) to JobParamter
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1/WorkloadManagement/Scouting/Scouting/JID_453605534 INFO: Job 453605534 set scouting status
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1/WorkloadManagement/Scouting INFO: [JID 453605534] Not in checking state. Avoid fast track
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1 INFO: Connect error failed: Peer closed connection
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1 NOTICE: Failed to reconnect. Sleeping for 1 seconds
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1 WARN: Issue getting socket: <DIRAC.Core.DISET.private.Transports.M2SSLTransport.SSLTransport object at 0x7f676041de10> : ('dips', 'cav08g01.cc.kek.jp', 9175, 'WorkloadManagement/OptimizationMind') : [Errno 111] Connection refused:ConnectionRefusedError(111, 'Connection refused')
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1 WARN: Non-responding URL temporarily banned dips://cav08g01.cc.kek.jp:9175/WorkloadManagement/OptimizationMind
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1 INFO: Retry connection : 1 to dips://cav08g01.cc.kek.jp:9175/WorkloadManagement/OptimizationMind
2025-01-21 16:44:30 UTC WorkloadManagement/Optimizers-1 INFO: Waiting 2.000000 seconds before retry all service(s)
2025-01-21 16:44:31 UTC WorkloadManagement/Optimizers-1 NOTICE: Trying to reconnect to WorkloadManagement/OptimizationMind
2025-01-21 16:44:32 UTC WorkloadManagement/Optimizers-1 INFO: Connect error failed: Already connected
2025-01-21 16:44:32 UTC WorkloadManagement/Optimizers-1 NOTICE: Failed to reconnect. Sleeping for 1 seconds
2025-01-21 16:44:32 UTC WorkloadManagement/Optimizers-1 WARN: Error while receiving message from (202.13.203.85:9175) : Peer closed connection
2025-01-21 16:44:32 UTC WorkloadManagement/Optimizers-1 NOTICE: Trying to reconnect to WorkloadManagement/OptimizationMind
2025-01-21 16:44:32 UTC WorkloadManagement/Optimizers-1 NOTICE: Reconnected to WorkloadManagement/OptimizationMind

For this time, I found following

2025-01-21 16:44:30 UTC WorkloadManagement/OptimizationMind WARN: Error while receiving message from ([::ffff:202.13.203.85]:44216)[hosts:cav08g01.cc.kek.jp] : Peer closed connection
2025-01-21 16:44:30 UTC WorkloadManagement/OptimizationMind INFO: Job 453605495: Ended trace execution
2025-01-21 16:44:30 UTC WorkloadManagement/OptimizationMind INFO: Job 453605493: Ended trace execution
2025-01-21 16:44:30 UTC WorkloadManagement/OptimizationMind INFO: Dispatching job 453605489 out of optimization
2025-01-21 16:44:30 UTC WorkloadManagement/OptimizationMind NOTICE: Executing action ([::ffff:202.13.203.85]:44216)[hosts:cav08g01.cc.kek.jp] Message/msg_TaskDone(<masked>)
2025-01-21 16:44:30 UTC WorkloadManagement/OptimizationMind NOTICE: Executing action unknown Connection/drop(<masked>)
2025-01-21 16:44:30 UTC WorkloadManagement/OptimizationMind WARN: Triggered conn_drop for ::ffff:202.13.203.85:9175->::ffff:202.13.203.85:44216
2025-01-21 16:44:30 UTC WorkloadManagement/OptimizationMind/ExecutorDispatcher INFO: Removing executor ::ffff:202.13.203.85:9175->::ffff:202.13.203.85:44216