Skip to content
This repository has been archived by the owner on Mar 8, 2023. It is now read-only.

How to reconnect within a short period of time? #18

Open
ceezous opened this issue Feb 7, 2022 · 8 comments
Open

How to reconnect within a short period of time? #18

ceezous opened this issue Feb 7, 2022 · 8 comments

Comments

@ceezous
Copy link

ceezous commented Feb 7, 2022

I'm now conducting reconnection by establishing a new connection, which cost me about 30s to wait.
Is there an official API to do this? And is it able to reduce the reconnecting time to less than 10s?
@rostest
Copy link
Collaborator

rostest commented Feb 7, 2022

Thanks for your message. We recommend to use the sick_scan_xd driver on https://github.com/SICKAG/sick_scan_xd, which reconnects automatically as soon as possible after network errors.

@ceezous
Copy link
Author

ceezous commented Feb 9, 2022

@rostest Thanks for the reply. I would like to switch to the sick_scan_xd driver if I have more time, but my team has already implement the previous lib (sick_scan_base) in our codes and it works well except the reconnection time, so I'm wondering if there's a good way to perform a faster reconnection funtionality based on sick_scan_base? That would be really nice :)

@rostest
Copy link
Collaborator

rostest commented Feb 10, 2022

Can you give some more details or screenshots about connection losts, timeouts and the scanner you're using? Is it right that a reconnection is delayed due to waiting for a timeout after network errors?
An alternative might be just to kill and restart sick_generic_caller in case of timeouts, without waiting for sick_generic_caller to finish. Another alternative is to patch the sources to decrease the timeout, e.g. to call tcp recv with non-blocking-flags and to exit after some seconds without receiving any data.

@ceezous
Copy link
Author

ceezous commented Feb 22, 2022 •
edited
Loading

Sure. I added some log into sick_scan_base and output it in a file.
I manually disconnected the laser physically and reconnected, I found that it will try to reconnect about 3 or 4 times, and each time, there would be about 7 seconds cost in ‘init_scanner’, which results in 30s latency.
I'm wondering if there is some way to deal with it?

here is the log content:

==================================================================
Tue Feb 22 16:12:29 2022
Func 'SickScanCommon::init':
Before init_device()

Tue Feb 22 16:12:29 2022
Func 'SickScanCommon::init':
After init_device()
result:0

==================================================================
Tue Feb 22 16:12:29 2022
Func 'SickScanCommon::init':
Before init_scanner()

Tue Feb 22 16:12:29 2022
Func 'SickScanCommon::init':
After init_scanner()
result:0

==================================================================
Tue Feb 22 16:12:38 2022
Func 'SickScanCommon::init':
Before init_device()

Tue Feb 22 16:12:41 2022
Func 'SickScanCommon::init':
After init_device()
result:0

==================================================================
Tue Feb 22 16:12:41 2022
Func 'SickScanCommon::init':
Before init_scanner()

Tue Feb 22 16:12:48 2022
Func 'SickScanCommon::init':
After init_scanner()
result:1

==================================================================
Tue Feb 22 16:12:49 2022
Func 'SickScanCommon::init':
Before init_device()

Tue Feb 22 16:12:49 2022
Func 'SickScanCommon::init':
After init_device()
result:0

==================================================================
Tue Feb 22 16:12:49 2022
Func 'SickScanCommon::init':
Before init_scanner()

Tue Feb 22 16:12:56 2022
Func 'SickScanCommon::init':
After init_scanner()
result:1

==================================================================
Tue Feb 22 16:12:58 2022
Func 'SickScanCommon::init':
Before init_device()

Tue Feb 22 16:12:58 2022
Func 'SickScanCommon::init':
After init_device()
result:0

==================================================================
Tue Feb 22 16:12:58 2022
Func 'SickScanCommon::init':
Before init_scanner()

Tue Feb 22 16:13:05 2022
Func 'SickScanCommon::init':
After init_scanner()
result:1

==================================================================
Tue Feb 22 16:13:06 2022
Func 'SickScanCommon::init':
Before init_device()

Tue Feb 22 16:13:06 2022
Func 'SickScanCommon::init':
After init_device()
result:0

==================================================================
Tue Feb 22 16:13:06 2022
Func 'SickScanCommon::init':
Before init_scanner()

Tue Feb 22 16:13:07 2022
Func 'SickScanCommon::init':
After init_scanner()
result:0

@rostest
Copy link
Collaborator

rostest commented Feb 23, 2022

Thanks for profiling! Some lidars require up to 30 seconds to get ready after disconnected standby (time to accelerate the motor, get a stable rotational speed and so on).

Which lidar do you use?

Can you post the driver messages during startup (i.e. from sick_generic_caller start until connection successfully established)? If the driver is waiting for the lidar to get ready, I'd expect some "waiting for ..." messages.

Delays and possibly unnecessary reconnections can be caused by switching Cola-Ascii to Cola-Binary communication, too. In this case, a message "Waiting for timeout... communication mode is changed..." would appear. To avoid delays due to communication mode switching, it's recommended to set binary communication using SOPAS ET and save the scanner settings in its EEPROM. Please attach a log or screenshot of the driver messages during startup for further diagnosis.

@ceezous
Copy link
Author

ceezous commented Mar 31, 2022

Sorry for this late reply.

We're using SickTim561. And I'll paste the log in next chat box.
For convenience, here is some useful info: the restarting process lasts from 17:35:34.823 to 17:36:14.703, which you can refer to.

@ceezous
Copy link
Author

ceezous commented Apr 1, 2022

new sick laser
ROS_INFO: Publishing laserscan-pointcloud2 to
[Info],2022-03-31 17:35:33.456,5492,Func 'SickTim561Official' start.
[Info],2022-03-31 17:35:33.456,5492,Func 'SickTim561Official' end.
[Info],2022-03-31 17:35:33.456,5492,Func 'open' start.
[Info],2022-03-31 17:35:33.456,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:35:33.456,5492,Func 'set_looping_state':
New state is '0'
[Info],2022-03-31 17:35:33.456,5492,Func 'set_looping_state' end.
[Info],2022-03-31 17:35:33.456,24368,Func 'thread_loop' start.
ROS_INFO: Parameter setting for <active_echo: 0>
ROS_DEBUG: Command: sMN SetAccessMode 3 F4724744
ROS_INFO: Sending : sMN SetAccessMode 3 F4724744
ROS_INFO: Receiving: sAN SetAccessMode 1
ROS_DEBUG: Command: sWN EIHstCola 0
ROS_INFO: Sending : sWN EIHstCola 0
ROS_INFO: Receiving: sWA EIHstCola
ROS_DEBUG: Command: sRN FirmwareVersion
ROS_INFO: Sending : sRN FirmwareVersion
ROS_INFO: Receiving: sRA FirmwareVersion 5 V2.61
[Info],2022-03-31 17:35:33.457,24368,Func 'thread_loop':
Start to run 'sock->init()'.
ROS_DEBUG: Command: sRN SCdevicestate
ROS_INFO: Sending : sRN SCdevicestate
ROS_INFO: Receiving: sRA SCdevicestate 0
ROS_DEBUG: Laser is busy
ROS_DEBUG: Command: sRN ODoprh
ROS_INFO: Sending : sRN ODoprh
ROS_INFO: Receiving: sRA ODoprh 6B1A
ROS_DEBUG: Command: sRN ODpwrc
ROS_INFO: Sending : sRN ODpwrc
ROS_INFO: Receiving: sRA ODpwrc 32
ROS_DEBUG: Command: sRN LocationName
ROS_INFO: Sending : sRN LocationName
ROS_INFO: Receiving: sRA LocationName B not defined
ROS_INFO: Sending : sRN LMPoutputRange
ROS_INFO: Receiving: sRA LMPoutputRange 1 D05 FFF92230 225510
ROS_INFO: Angle resolution of scanner is 0.33330 [deg] (in 1/10000th deg: 0xD05)
ROS_INFO: [From:To] -45.00000 [deg] to 225.00000 [deg] (in 1/10000th deg: from 0xFFF92230 to 0x225510)
ROS_INFO: MIN_ANG: -2.356 [rad] -135.000 [deg]
ROS_INFO: MAX_ANG: 2.356 [rad] 135.000 [deg]
ROS_INFO: Sending : sWN LMPoutputRange 1 D05 FFF92230 225510 D05 FFF92230 225510 D05 FFF92230 225510 D05 FFF92230 225510
ROS_INFO: Receiving: sWA LMPoutputRange
ROS_INFO: Sending : sRN LMPoutputRange
ROS_INFO: Receiving: sRA LMPoutputRange 1 D05 FFF92230 225510
ROS_INFO: Angle resolution of scanner is 0.33330 [deg] (in 1/10000th deg: 0xD05)
ROS_INFO: MIN_ANG (after command verification): -2.356 [rad] -135.000 [deg]
ROS_INFO: MAX_ANG (after command verification): 2.356 [rad] 135.000 [deg]
ROS_INFO: Sending : sWN LMDscandatacfg 01 00 0 0 0 0 00 0 0 0 1 1
ROS_INFO: Receiving: sWA LMDscandatacfg
ROS_INFO: Sending : sRN LMDscandatacfg
ROS_INFO: Receiving: sRA LMDscandatacfg 1 0 0 0 0 0 0 0 0 0 1 1
ROS_DEBUG: Command: sMN LMCstartmeas
ROS_INFO: Sending : sMN LMCstartmeas
ROS_INFO: Receiving: sAN LMCstartmeas 0
ROS_DEBUG: Command: sMN Run
ROS_INFO: Sending : sMN Run
ROS_INFO: Receiving: sAN Run 1
ROS_DEBUG: Command: sEN LMDscandata 1
ROS_INFO: Sending : sEN LMDscandata 1
ROS_INFO: Receiving: sEA LMDscandata 1
ROS_DEBUG: Starting scan data ....

[Info],2022-03-31 17:35:33.848,24368,Func 'thread_loop':
init_result:0
get_ip():192.168.1.100
get_port():2111
ROS_DEBUG: Number of data: 811
MSG received...[Info],2022-03-31 17:35:34.034,24368,Func 'set_looping_state' start.
[Info],2022-03-31 17:35:34.034,24368,Func 'set_looping_state':
New state is '1'
[Info],2022-03-31 17:35:34.034,24368,Func 'set_looping_state' end.

Current time:0
=====> frame index: 1 grab_time: 1.64872e+12ms time_gap: 1
ROS_DEBUG: Number of data: 811
MSG received...=====> frame index: 2 grab_time: 1.64872e+12ms time_gap: 9
[Info],2022-03-31 17:35:34.034,5492,Func 'open':
New looping state:1
[Info],2022-03-31 17:35:34.034,5492,Func 'open' end.
ROS_DEBUG: Number of data: 811
MSG received...=====> frame index: 3 grab_time: 1.64872e+12ms time_gap: 14
ROS_DEBUG: Number of data: 811
MSG received...=====> frame index: 4 grab_time: 1.64872e+12ms time_gap: 18
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 5 grab_time: 1.64872e+12ms time_gap: 23
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 6 grab_time: 1.64872e+12ms time_gap: 29
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 7 grab_time: 1.64872e+12ms time_gap: 33
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 8 grab_time: 1.64872e+12ms time_gap: 39
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 9 grab_time: 1.64872e+12ms time_gap: 44
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 10 grab_time: 1.64872e+12ms time_gap: 48
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 11 grab_time: 1.64872e+12ms time_gap: 50
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> Start to reboot.
Func 'reboot':
Start to run 'close()'.[Info],2022-03-31 17:35:34.823,5492,Func 'reboot' start.
[Info],2022-03-31 17:35:34.823,5492,Func 'reboot':
Start to run 'close()'.
[Info],2022-03-31 17:35:34.823,5492,Func 'close' start.
[Info],2022-03-31 17:35:34.823,5492,Func 'close':
Current state is 'LOOP_STATE::RUNNING'.
[Info],2022-03-31 17:35:34.823,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:35:34.823,5492,Func 'set_looping_state':
New state is '2'
[Info],2022-03-31 17:35:34.823,5492,Func 'set_looping_state' end.
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
[Info],2022-03-31 17:35:34.832,24368,Func 'thread_loop':
Outside loop, start to stop sock.

SOPAS - Stopped streaming scan data.
aaa.[Info],2022-03-31 17:35:34.845,24368,Func 'thread_loop':
stopScanData() finished
[Info],2022-03-31 17:35:34.845,24368,Func 'thread_loop':
End stopping sock.
[Info],2022-03-31 17:35:34.845,24368,Func 'set_looping_state' start.
[Info],2022-03-31 17:35:34.845,24368,Func 'set_looping_state':
New state is '3'
[Info],2022-03-31 17:35:34.845,24368,Func 'set_looping_state' end.
ROS_WARN: Disconnecting TCP-Connection.
ERROR: Tcp::readInputData: Failed to read data from socket, aborting!
sick_scan driver exiting.
[Info],2022-03-31 17:35:34.845,24368,Func 'thread_loop' end.
[Info],2022-03-31 17:35:34.867,5492,Func 'close' end.
[Info],2022-03-31 17:35:34.867,5492,Func 'reboot':
Finished running 'close()'.
[Info],2022-03-31 17:35:35.868,5492,Func 'reboot':
Change port from 2111 to 2112
[Info],2022-03-31 17:35:35.868,5492,Func 'reboot':
Start to run 'open()'.
[Info],2022-03-31 17:35:35.868,5492,Func 'open' start.
[Info],2022-03-31 17:35:35.868,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:35:35.868,5492,Func 'set_looping_state':
New state is '0'
[Info],2022-03-31 17:35:35.868,5492,Func 'set_looping_state' end.
[Info],2022-03-31 17:35:35.869,22284,Func 'thread_loop' start.
ROS_INFO: Publishing laserscan-pointcloud2 to
[Info],2022-03-31 17:35:35.870,22284,Func 'thread_loop':
Start to run 'sock->init()'.
ROS_INFO: Parameter setting for <active_echo: 0>
ROS_DEBUG: Command: sMN SetAccessMode 3 F4724744
ROS_INFO: Sending : sMN SetAccessMode 3 F4724744
ROS_INFO: Receiving: sAN SetAccessMode 1
ROS_DEBUG: Command: sWN EIHstCola 0
ROS_INFO: Sending : sWN EIHstCola 0
ROS_INFO: Receiving: sWA EIHstCola
ROS_DEBUG: Command: sRN FirmwareVersion
ROS_INFO: Sending : sRN FirmwareVersion
ROS_INFO: Receiving: sRA FirmwareVersion 5 V2.61
ROS_DEBUG: Command: sRN SCdevicestate
ROS_INFO: Sending : sRN SCdevicestate
ROS_INFO: Receiving: sRA SCdevicestate 0
ROS_DEBUG: Laser is busy
ROS_DEBUG: Command: sRN ODoprh
ROS_INFO: Sending : sRN ODoprh
ROS_INFO: Receiving: sRA ODoprh 6B1A
ROS_DEBUG: Command: sRN ODpwrc
ROS_INFO: Sending : sRN ODpwrc
ROS_INFO: Receiving: sRA ODpwrc 32
ROS_DEBUG: Command: sRN LocationName
ROS_INFO: Sending : sRN LocationName
ROS_INFO: Receiving: sRA LocationName B not defined
ROS_INFO: Sending : sRN LMPoutputRange
ROS_INFO: Receiving: sRA LMPoutputRange 1 D05 FFF92230 225510
ROS_INFO: Angle resolution of scanner is 0.33330 [deg] (in 1/10000th deg: 0xD05)
ROS_INFO: [From:To] -45.00000 [deg] to 225.00000 [deg] (in 1/10000th deg: from 0xFFF92230 to 0x225510)
ROS_INFO: MIN_ANG: -2.356 [rad] -135.000 [deg]
ROS_INFO: MAX_ANG: 2.356 [rad] 135.000 [deg]
ROS_INFO: Sending : sWN LMPoutputRange 1 D05 FFF92230 225510 D05 FFF92230 225510 D05 FFF92230 225510 D05 FFF92230 225510
ROS_INFO: Receiving: sWA LMPoutputRange
ROS_INFO: Sending : sRN LMPoutputRange
ROS_INFO: Receiving: sRA LMPoutputRange 1 D05 FFF92230 225510
ROS_INFO: Angle resolution of scanner is 0.33330 [deg] (in 1/10000th deg: 0xD05)
ROS_INFO: MIN_ANG (after command verification): -2.356 [rad] -135.000 [deg]
ROS_INFO: MAX_ANG (after command verification): 2.356 [rad] 135.000 [deg]
ROS_INFO: Sending : sWN LMDscandatacfg 01 00 0 0 0 0 00 0 0 0 1 1
ROS_INFO: Receiving: sWA LMDscandatacfg
ROS_INFO: Sending : sRN LMDscandatacfg
ROS_INFO: Receiving: sRA LMDscandatacfg 1 0 0 0 0 0 0 0 0 0 1 1
ROS_DEBUG: Command: sMN LMCstartmeas
ROS_INFO: Sending : sMN LMCstartmeas
ROS_INFO: Receiving: sAN LMCstartmeas 0
ROS_DEBUG: Command: sMN Run
ROS_INFO: Sending : sMN Run
ROS_INFO: Receiving: sAN Run 1
ROS_DEBUG: Command: sEN LMDscandata 1
ROS_INFO: Sending : sEN LMDscandata 1
ROS_INFO: Receiving: sEA LMDscandata 1
ROS_DEBUG: Starting scan data ....

[Info],2022-03-31 17:35:36.230,22284,Func 'thread_loop':
init_result:0
get_ip():192.168.1.100
get_port():2112
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
[Info],2022-03-31 17:35:36.434,22284,Func 'set_looping_state' start.
[Info],2022-03-31 17:35:36.434,22284,Func 'set_looping_state':
New state is '1'
[Info],2022-03-31 17:35:36.434,22284,Func 'set_looping_state' end.
=====> Succeeded in rebooting.

Current time:2
=====> frame index: 1 grab_time: 1.64872e+12ms time_gap: 2
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 2 grab_time: 1.64872e+12ms time_gap: 8
[Info],2022-03-31 17:35:36.434,5492,Func 'open':
New looping state:1
[Info],2022-03-31 17:35:36.434,5492,Func 'open' end.
[Info],2022-03-31 17:35:36.434,5492,Func 'reboot':
The result of 'open()' is true
[Info],2022-03-31 17:35:36.434,5492,Func 'reboot' end.
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 3 grab_time: 1.64872e+12ms time_gap: 15
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 4 grab_time: 1.64872e+12ms time_gap: 20
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 5 grab_time: 1.64872e+12ms time_gap: 23
ERROR: Tcp::readInputData: Failed to read data from socket, aborting!
ROS_WARN: Timeout during waiting for new datagram
Read Error when getting datagram: 1.
=====> Start to reboot.
Func 'reboot':
Start to run 'close()'.[Info],2022-03-31 17:35:37.225,5492,Func 'reboot' start.
[Info],2022-03-31 17:35:37.225,5492,Func 'reboot':
Start to run 'close()'.
[Info],2022-03-31 17:35:37.225,5492,Func 'close' start.
[Info],2022-03-31 17:35:37.225,5492,Func 'close':
Current state is 'LOOP_STATE::RUNNING'.
[Info],2022-03-31 17:35:37.225,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:35:37.225,5492,Func 'set_looping_state':
New state is '2'
[Info],2022-03-31 17:35:37.225,5492,Func 'set_looping_state' end.
ROS_WARN: Timeout during waiting for new datagram
Read Error when getting datagram: 1.
Warning: Tcp::write: Failed to send data to socket.
[Info],2022-03-31 17:35:37.720,22284,Func 'thread_loop':
Outside loop, start to stop sock.
no answer received after 500 ms. Maybe sopas mode is wrong.

SOPAS - Error stopping streaming scan data!
aaa.[Info],2022-03-31 17:35:38.298,22284,Func 'thread_loop':
stopScanData() finished
[Info],2022-03-31 17:35:38.298,22284,Func 'thread_loop':
End stopping sock.
[Info],2022-03-31 17:35:38.298,22284,Func 'set_looping_state' start.
[Info],2022-03-31 17:35:38.298,22284,Func 'set_looping_state':
New state is '3'
[Info],2022-03-31 17:35:38.298,22284,Func 'set_looping_state' end.
ROS_WARN: Disconnecting TCP-Connection.
sick_scan driver exiting.
[Info],2022-03-31 17:35:38.299,22284,Func 'thread_loop' end.
[Info],2022-03-31 17:35:38.300,5492,Func 'close' end.
[Info],2022-03-31 17:35:38.300,5492,Func 'reboot':
Finished running 'close()'.
[Info],2022-03-31 17:35:39.300,5492,Func 'reboot':
Change port from 2112 to 2111
[Info],2022-03-31 17:35:39.300,5492,Func 'reboot':
Start to run 'open()'.
[Info],2022-03-31 17:35:39.300,5492,Func 'open' start.
[Info],2022-03-31 17:35:39.300,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:35:39.300,5492,Func 'set_looping_state':
New state is '0'
[Info],2022-03-31 17:35:39.300,5492,Func 'set_looping_state' end.
[Info],2022-03-31 17:35:39.302,28408,Func 'thread_loop' start.
ROS_INFO: Publishing laserscan-pointcloud2 to
[Info],2022-03-31 17:35:39.303,28408,Func 'thread_loop':
Start to run 'sock->init()'.
ROS_INFO: Parameter setting for <active_echo: 0>
ROS_DEBUG: Command: sMN SetAccessMode 3 F4724744
ROS_INFO: Sending : sMN SetAccessMode 3 F4724744
no answer received after 2000 ms. Maybe sopas mode is wrong.

ROS_INFO: Receiving:
ROS_INFO: SOPAS Communication -Error unexpected Sopas Answer for request sMN SetAccessMode 3 F4724744

ROS_INFO: Sending : <Len=0023>sMN SetAccessMode 0x03 0xf4 0x72 0x47 0x44 CRC:<0xb3>
no answer received after 2000 ms. Maybe sopas mode is wrong.

ROS_INFO: Receiving:
ROS_INFO: SOPAS Communication -Error unexpected Sopas Answer for request <Len=0023>sMN SetAccessMode 0x03 0xf4 0x72 0x47 0x44 CRC:<0xb3>

Error Access Mode
ROS_DEBUG: Command: sWN EIHstCola 0
ROS_INFO: Sending : <Len=0015>sWN EIHstCola 0x00 CRC:<0x08>
no answer received after 2000 ms. Maybe sopas mode is wrong.

ROS_INFO: Receiving:
ROS_INFO: SOPAS Communication -Error unexpected Sopas Answer for request <Len=0015>sWN EIHstCola 0x00 CRC:<0x08>

Command or Error message not defined
ROS_INFO: Failed to init scanner Error Code: 1
Waiting for timeout...
If the communication mode set in the scanner memory is different from that used by the driver, the scanner's communication mode is changed.
This requires a restart of the TCP-IP connection, which can extend the start time by up to 30 seconds. There are two ways to prevent this:

  1. [Recommended] Set the communication mode with the SOPAS ET software to binary and save this setting in the scanner's EEPROM.
  2. Use the parameter "use_binary_protocol" to overwrite the default settings of the driver.
    ROS_WARN: Disconnecting TCP-Connection.[Info],2022-03-31 17:35:46.337,28408,Func 'thread_loop':
    init_result:1
    get_ip():192.168.1.100
    get_port():2111
    [Info],2022-03-31 17:35:46.337,28408,Func 'set_looping_state' start.
    [Info],2022-03-31 17:35:46.337,28408,Func 'set_looping_state':
    New state is '3'
    [Info],2022-03-31 17:35:46.337,28408,Func 'set_looping_state' end.
    [Info],2022-03-31 17:35:46.337,5492,Func 'open':
    New looping state:3
    [Info],2022-03-31 17:35:46.337,5492,Func 'open' end.
    [Info],2022-03-31 17:35:46.337,5492,Func 'reboot':
    The result of 'open()' is false
    [Info],2022-03-31 17:35:46.337,5492,Func 'reboot' end.
    =====> Failed to reboot.

Current time:
12
ERROR: Tcp::readInputData: Failed to read data from socket, aborting!
sick_scan driver exiting.
=====> Start to reboot.
Func 'reboot':
Start to run 'close()'.[Info],2022-03-31 17:35:47.122,5492,Func 'reboot' start.
[Info],2022-03-31 17:35:47.122,5492,Func 'reboot':
Start to run 'close()'.
[Info],2022-03-31 17:35:47.122,5492,Func 'close' start.
[Info],2022-03-31 17:35:47.122,5492,Func 'close' end.
[Info],2022-03-31 17:35:47.122,5492,Func 'reboot':
Finished running 'close()'.
[Info],2022-03-31 17:35:48.122,5492,Func 'reboot':
Change port from 2111 to 2112
[Info],2022-03-31 17:35:48.122,5492,Func 'reboot':
Start to run 'open()'.
[Info],2022-03-31 17:35:48.122,5492,Func 'open' start.
[Info],2022-03-31 17:35:48.122,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:35:48.122,5492,Func 'set_looping_state':
New state is '0'
[Info],2022-03-31 17:35:48.122,5492,Func 'set_looping_state' end.
[Info],2022-03-31 17:35:48.124,24804,Func 'thread_loop' start.
ROS_INFO: Publishing laserscan-pointcloud2 to
[Info],2022-03-31 17:35:48.125,24804,Func 'thread_loop':
Start to run 'sock->init()'.
ROS_INFO: Parameter setting for <active_echo: 0>
ROS_DEBUG: Command: sMN SetAccessMode 3 F4724744
ROS_INFO: Sending : sMN SetAccessMode 3 F4724744
no answer received after 2000 ms. Maybe sopas mode is wrong.

ROS_INFO: Receiving:
ROS_INFO: SOPAS Communication -Error unexpected Sopas Answer for request sMN SetAccessMode 3 F4724744

ROS_INFO: Sending : <Len=0023>sMN SetAccessMode 0x03 0xf4 0x72 0x47 0x44 CRC:<0xb3>
no answer received after 2000 ms. Maybe sopas mode is wrong.

ROS_INFO: Receiving:
ROS_INFO: SOPAS Communication -Error unexpected Sopas Answer for request <Len=0023>sMN SetAccessMode 0x03 0xf4 0x72 0x47 0x44 CRC:<0xb3>

Error Access Mode
ROS_DEBUG: Command: sWN EIHstCola 0
ROS_INFO: Sending : <Len=0015>sWN EIHstCola 0x00 CRC:<0x08>
no answer received after 2000 ms. Maybe sopas mode is wrong.

ROS_INFO: Receiving:
ROS_INFO: SOPAS Communication -Error unexpected Sopas Answer for request <Len=0015>sWN EIHstCola 0x00 CRC:<0x08>

Command or Error message not defined
ROS_INFO: Failed to init scanner Error Code: 1
Waiting for timeout...
If the communication mode set in the scanner memory is different from that used by the driver, the scanner's communication mode is changed.
This requires a restart of the TCP-IP connection, which can extend the start time by up to 30 seconds. There are two ways to prevent this:

  1. [Recommended] Set the communication mode with the SOPAS ET software to binary and save this setting in the scanner's EEPROM.
  2. Use the parameter "use_binary_protocol" to overwrite the default settings of the driver.
    ROS_WARN: Disconnecting TCP-Connection.
    =====> Failed to reboot.

Current time:21
[Info],2022-03-31 17:35:55.179,24804,Func 'thread_loop':
init_result:1
get_ip():192.168.1.100
get_port():2112
[Info],2022-03-31 17:35:55.179,24804,Func 'set_looping_state' start.
[Info],2022-03-31 17:35:55.179,24804,Func 'set_looping_state':
New state is '3'
[Info],2022-03-31 17:35:55.179,24804,Func 'set_looping_state' end.
[Info],2022-03-31 17:35:55.179,5492,Func 'open':
New looping state:3
[Info],2022-03-31 17:35:55.179,5492,Func 'open' end.
[Info],2022-03-31 17:35:55.179,5492,Func 'reboot':
The result of 'open()' is false
[Info],2022-03-31 17:35:55.179,5492,Func 'reboot' end.
ERROR: Tcp::readInputData: Failed to read data from socket, aborting!
sick_scan driver exiting.
=====> Start to reboot.
Func 'reboot':
Start to run 'close()'.[Info],2022-03-31 17:35:55.966,5492,Func 'reboot' start.
[Info],2022-03-31 17:35:55.966,5492,Func 'reboot':
Start to run 'close()'.
[Info],2022-03-31 17:35:55.966,5492,Func 'close' start.
[Info],2022-03-31 17:35:55.966,5492,Func 'close' end.
[Info],2022-03-31 17:35:55.966,5492,Func 'reboot':
Finished running 'close()'.
[Info],2022-03-31 17:35:56.966,5492,Func 'reboot':
Change port from 2112 to 2111
[Info],2022-03-31 17:35:56.966,5492,Func 'reboot':
Start to run 'open()'.
[Info],2022-03-31 17:35:56.966,5492,Func 'open' start.
[Info],2022-03-31 17:35:56.966,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:35:56.966,5492,Func 'set_looping_state':
New state is '0'
[Info],2022-03-31 17:35:56.966,5492,Func 'set_looping_state' end.
[Info],2022-03-31 17:35:56.968,25808,Func 'thread_loop' start.
ROS_INFO: Publishing laserscan-pointcloud2 to
[Info],2022-03-31 17:35:56.968,25808,Func 'thread_loop':
Start to run 'sock->init()'.
ROS_INFO: Parameter setting for <active_echo: 0>
ROS_DEBUG: Command: sMN SetAccessMode 3 F4724744
ROS_INFO: Sending : sMN SetAccessMode 3 F4724744
no answer received after 2000 ms. Maybe sopas mode is wrong.

ROS_INFO: Receiving:
ROS_INFO: SOPAS Communication -Error unexpected Sopas Answer for request sMN SetAccessMode 3 F4724744

ROS_INFO: Sending : <Len=0023>sMN SetAccessMode 0x03 0xf4 0x72 0x47 0x44 CRC:<0xb3>
no answer received after 2000 ms. Maybe sopas mode is wrong.

ROS_INFO: Receiving:
ROS_INFO: SOPAS Communication -Error unexpected Sopas Answer for request <Len=0023>sMN SetAccessMode 0x03 0xf4 0x72 0x47 0x44 CRC:<0xb3>

Error Access Mode
ROS_DEBUG: Command: sWN EIHstCola 0
ROS_INFO: Sending : <Len=0015>sWN EIHstCola 0x00 CRC:<0x08>
no answer received after 2000 ms. Maybe sopas mode is wrong.

ROS_INFO: Receiving:
ROS_INFO: SOPAS Communication -Error unexpected Sopas Answer for request <Len=0015>sWN EIHstCola 0x00 CRC:<0x08>

Command or Error message not defined
ROS_INFO: Failed to init scanner Error Code: 1
Waiting for timeout...
If the communication mode set in the scanner memory is different from that used by the driver, the scanner's communication mode is changed.
This requires a restart of the TCP-IP connection, which can extend the start time by up to 30 seconds. There are two ways to prevent this:

  1. [Recommended] Set the communication mode with the SOPAS ET software to binary and save this setting in the scanner's EEPROM.
  2. Use the parameter "use_binary_protocol" to overwrite the default settings of the driver.
    [Info],2022-03-31 17:36:04.005,25808,Func 'thread_loop':
    init_result:1
    get_ip():192.168.1.100
    get_port():2111
    [Info],2022-03-31 17:36:04.005,25808,Func 'set_looping_state' start.
    [Info],2022-03-31 17:36:04.005,25808,Func 'set_looping_state':
    New state is '3'
    ROS_WARN: [Info],2022-03-31 17:36:04.007,25808,Func 'set_looping_state' end.
    Disconnecting TCP-Connection.
    =====> Failed to reboot.
    ERROR: Tcp::readInputData: Failed to read data from socket, aborting!

Current time:29
sick_scan driver exiting.
[Info],2022-03-31 17:36:04.007,5492,Func 'open':
New looping state:3
[Info],2022-03-31 17:36:04.007,5492,Func 'open' end.
[Info],2022-03-31 17:36:04.007,5492,Func 'reboot':
The result of 'open()' is false
[Info],2022-03-31 17:36:04.007,5492,Func 'reboot' end.
=====> Start to reboot.
Func 'reboot':
Start to run 'close()'.[Info],2022-03-31 17:36:04.796,5492,Func 'reboot' start.
[Info],2022-03-31 17:36:04.796,5492,Func 'reboot':
Start to run 'close()'.
[Info],2022-03-31 17:36:04.796,5492,Func 'close' start.
[Info],2022-03-31 17:36:04.796,5492,Func 'close' end.
[Info],2022-03-31 17:36:04.796,5492,Func 'reboot':
Finished running 'close()'.
[Info],2022-03-31 17:36:05.797,5492,Func 'reboot':
Change port from 2111 to 2112
[Info],2022-03-31 17:36:05.797,5492,Func 'reboot':
Start to run 'open()'.
[Info],2022-03-31 17:36:05.797,5492,Func 'open' start.
[Info],2022-03-31 17:36:05.797,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:05.797,5492,Func 'set_looping_state':
New state is '0'
[Info],2022-03-31 17:36:05.797,5492,Func 'set_looping_state' end.
[Info],2022-03-31 17:36:05.798,1264,Func 'thread_loop' start.
ROS_INFO: Publishing laserscan-pointcloud2 to
[Info],2022-03-31 17:36:05.799,1264,Func 'thread_loop':
Start to run 'sock->init()'.
ROS_INFO: Parameter setting for <active_echo: 0>
ROS_DEBUG: Command: sMN SetAccessMode 3 F4724744
ROS_INFO: Sending : sMN SetAccessMode 3 F4724744
ROS_INFO: Receiving: sAN SetAccessMode 1
ROS_DEBUG: Command: sWN EIHstCola 0
ROS_INFO: Sending : sWN EIHstCola 0
ROS_INFO: Receiving: sWA EIHstCola
ROS_DEBUG: Command: sRN FirmwareVersion
ROS_INFO: Sending : sRN FirmwareVersion
ROS_INFO: Receiving: sRA FirmwareVersion 5 V2.61
ROS_DEBUG: Command: sRN SCdevicestate
ROS_INFO: Sending : sRN SCdevicestate
ROS_INFO: Receiving: sRA SCdevicestate 0
ROS_DEBUG: Laser is busy
ROS_DEBUG: Command: sRN ODoprh
ROS_INFO: Sending : sRN ODoprh
ROS_INFO: Receiving: sRA ODoprh 6B1A
ROS_DEBUG: Command: sRN ODpwrc
ROS_INFO: Sending : sRN ODpwrc
ROS_INFO: Receiving: sRA ODpwrc 32
ROS_DEBUG: Command: sRN LocationName
ROS_INFO: Sending : sRN LocationName
ROS_INFO: Receiving: sRA LocationName B not defined
ROS_INFO: Sending : sRN LMPoutputRange
ROS_INFO: Receiving: sRA LMPoutputRange 1 D05 FFF92230 225510
ROS_INFO: Angle resolution of scanner is 0.33330 [deg] (in 1/10000th deg: 0xD05)
ROS_INFO: [From:To] -45.00000 [deg] to 225.00000 [deg] (in 1/10000th deg: from 0xFFF92230 to 0x225510)
ROS_INFO: MIN_ANG: -2.356 [rad] -135.000 [deg]
ROS_INFO: MAX_ANG: 2.356 [rad] 135.000 [deg]
ROS_INFO: Sending : sWN LMPoutputRange 1 D05 FFF92230 225510 D05 FFF92230 225510 D05 FFF92230 225510 D05 FFF92230 225510
ROS_INFO: Receiving: sWA LMPoutputRange
ROS_INFO: Sending : sRN LMPoutputRange
ROS_INFO: Receiving: sRA LMPoutputRange 1 D05 FFF92230 225510
ROS_INFO: Angle resolution of scanner is 0.33330 [deg] (in 1/10000th deg: 0xD05)
ROS_INFO: MIN_ANG (after command verification): -2.356 [rad] -135.000 [deg]
ROS_INFO: MAX_ANG (after command verification): 2.356 [rad] 135.000 [deg]
ROS_INFO: Sending : sWN LMDscandatacfg 01 00 0 0 0 0 00 0 0 0 1 1
ROS_INFO: Receiving: sWA LMDscandatacfg
ROS_INFO: Sending : sRN LMDscandatacfg
ROS_INFO: Receiving: sRA LMDscandatacfg 1 0 0 0 0 0 0 0 0 0 1 1
ROS_DEBUG: Command: sMN LMCstartmeas
ROS_INFO: Sending : sMN LMCstartmeas
ROS_INFO: Receiving: sAN LMCstartmeas 0
ROS_DEBUG: Command: sMN Run
ROS_INFO: Sending : sMN Run
ROS_INFO: Receiving: sAN Run 1
ROS_DEBUG: Command: sEN LMDscandata 1
ROS_INFO: Sending : sEN LMDscandata 1
ROS_INFO: Receiving: sEA LMDscandata 1
ROS_DEBUG: Starting scan data ....

[Info],2022-03-31 17:36:07.318,1264,Func 'thread_loop':
init_result:0
get_ip():192.168.1.100
get_port():2112
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> Succeeded in rebooting.

Current time:33
=====> frame index: 1 grab_time: 1.64872e+12ms time_gap: 2
[Info],2022-03-31 17:36:07.502,1264,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:07.502,1264,Func 'set_looping_state':
New state is '1'
[Info],2022-03-31 17:36:07.503,1264,Func 'set_looping_state' end.
[Info],2022-03-31 17:36:07.503,5492,Func 'open':
New looping state:1
[Info],2022-03-31 17:36:07.503,5492,Func 'open' end.
[Info],2022-03-31 17:36:07.503,5492,Func 'reboot':
The result of 'open()' is true
[Info],2022-03-31 17:36:07.503,5492,Func 'reboot' end.
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 2 grab_time: 1.64872e+12ms time_gap: 11
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 3 grab_time: 1.64872e+12ms time_gap: 16
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 4 grab_time: 1.64872e+12ms time_gap: 17
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 5 grab_time: 1.64872e+12ms time_gap: 24
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 6 grab_time: 1.64872e+12ms time_gap: 27
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 7 grab_time: 1.64872e+12ms time_gap: 29
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 8 grab_time: 1.64872e+12ms time_gap: 40
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 9 grab_time: 1.64872e+12ms time_gap: 44
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 10 grab_time: 1.64872e+12ms time_gap: 50
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
ROS_INFO: PANIC: Can not open ..\demo\scan.jpg_tmp for writing. Check existience of demo dir. or patch code.

ROS_INFO: PANIC: Can not open ..\demo\scan.csv_tmp for writing. Check existience of demo dir. or patch code.

=====> frame index: 11 grab_time: 1.64872e+12ms time_gap: 56
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> Start to reboot.
Func 'reboot':
Start to run 'close()'.[Info],2022-03-31 17:36:08.293,5492,Func 'reboot' start.
[Info],2022-03-31 17:36:08.293,5492,Func 'reboot':
Start to run 'close()'.
[Info],2022-03-31 17:36:08.293,5492,Func 'close' start.
[Info],2022-03-31 17:36:08.293,5492,Func 'close':
Current state is 'LOOP_STATE::RUNNING'.
[Info],2022-03-31 17:36:08.293,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:08.293,5492,Func 'set_looping_state':
New state is '2'
[Info],2022-03-31 17:36:08.293,5492,Func 'set_looping_state' end.
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
[Info],2022-03-31 17:36:08.299,1264,Func 'thread_loop':
Outside loop, start to stop sock.

SOPAS - Stopped streaming scan data.
aaa.[Info],2022-03-31 17:36:08.311,1264,Func 'thread_loop':
stopScanData() finished
[Info],2022-03-31 17:36:08.311,1264,Func 'thread_loop':
End stopping sock.
[Info],2022-03-31 17:36:08.311,1264,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:08.311,1264,Func 'set_looping_state':
New state is '3'
[Info],2022-03-31 17:36:08.311,1264,Func 'set_looping_state' end.
ROS_WARN: Disconnecting TCP-Connection.
ERROR: Tcp::readInputData: Failed to read data from socket, aborting!
sick_scan driver exiting.
[Info],2022-03-31 17:36:08.313,1264,Func 'thread_loop' end.
[Info],2022-03-31 17:36:08.315,5492,Func 'close' end.
[Info],2022-03-31 17:36:08.315,5492,Func 'reboot':
Finished running 'close()'.
[Info],2022-03-31 17:36:09.316,5492,Func 'reboot':
Change port from 2112 to 2111
[Info],2022-03-31 17:36:09.316,5492,Func 'reboot':
Start to run 'open()'.
[Info],2022-03-31 17:36:09.316,5492,Func 'open' start.
[Info],2022-03-31 17:36:09.316,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:09.316,5492,Func 'set_looping_state':
New state is '0'
[Info],2022-03-31 17:36:09.316,5492,Func 'set_looping_state' end.
[Info],2022-03-31 17:36:09.317,20788,Func 'thread_loop' start.
ROS_INFO: Publishing laserscan-pointcloud2 to
[Info],2022-03-31 17:36:09.317,20788,Func 'thread_loop':
Start to run 'sock->init()'.
ROS_INFO: Parameter setting for <active_echo: 0>
ROS_DEBUG: Command: sMN SetAccessMode 3 F4724744
ROS_INFO: Sending : sMN SetAccessMode 3 F4724744
ROS_INFO: Receiving: sAN SetAccessMode 1
ROS_DEBUG: Command: sWN EIHstCola 0
ROS_INFO: Sending : sWN EIHstCola 0
ROS_INFO: Receiving: sWA EIHstCola
ROS_DEBUG: Command: sRN FirmwareVersion
ROS_INFO: Sending : sRN FirmwareVersion
ROS_INFO: Receiving: sRA FirmwareVersion 5 V2.61
ROS_DEBUG: Command: sRN SCdevicestate
ROS_INFO: Sending : sRN SCdevicestate
ROS_INFO: Receiving: sRA SCdevicestate 0
ROS_DEBUG: Laser is busy
ROS_DEBUG: Command: sRN ODoprh
ROS_INFO: Sending : sRN ODoprh
ROS_INFO: Receiving: sRA ODoprh 6B1A
ROS_DEBUG: Command: sRN ODpwrc
ROS_INFO: Sending : sRN ODpwrc
ROS_INFO: Receiving: sRA ODpwrc 32
ROS_DEBUG: Command: sRN LocationName
ROS_INFO: Sending : sRN LocationName
ROS_INFO: Receiving: sRA LocationName B not defined
ROS_INFO: Sending : sRN LMPoutputRange
ROS_INFO: Receiving: sRA LMPoutputRange 1 D05 FFF92230 225510
ROS_INFO: Angle resolution of scanner is 0.33330 [deg] (in 1/10000th deg: 0xD05)
ROS_INFO: [From:To] -45.00000 [deg] to 225.00000 [deg] (in 1/10000th deg: from 0xFFF92230 to 0x225510)
ROS_INFO: MIN_ANG: -2.356 [rad] -135.000 [deg]
ROS_INFO: MAX_ANG: 2.356 [rad] 135.000 [deg]
ROS_INFO: Sending : sWN LMPoutputRange 1 D05 FFF92230 225510 D05 FFF92230 225510 D05 FFF92230 225510 D05 FFF92230 225510
ROS_INFO: Receiving: sWA LMPoutputRange
ROS_INFO: Sending : sRN LMPoutputRange
ROS_INFO: Receiving: sRA LMPoutputRange 1 D05 FFF92230 225510
ROS_INFO: Angle resolution of scanner is 0.33330 [deg] (in 1/10000th deg: 0xD05)
ROS_INFO: MIN_ANG (after command verification): -2.356 [rad] -135.000 [deg]
ROS_INFO: MAX_ANG (after command verification): 2.356 [rad] 135.000 [deg]
ROS_INFO: Sending : sWN LMDscandatacfg 01 00 0 0 0 0 00 0 0 0 1 1
ROS_INFO: Receiving: sWA LMDscandatacfg
ROS_INFO: Sending : sRN LMDscandatacfg
ROS_INFO: Receiving: sRA LMDscandatacfg 1 0 0 0 0 0 0 0 0 0 1 1
ROS_DEBUG: Command: sMN LMCstartmeas
ROS_INFO: Sending : sMN LMCstartmeas
ROS_INFO: Receiving: sAN LMCstartmeas 0
ROS_DEBUG: Command: sMN Run
ROS_INFO: Sending : sMN Run
ROS_INFO: Receiving: sAN Run 1
ROS_DEBUG: Command: sEN LMDscandata 1
ROS_INFO: Sending : sEN LMDscandata 1
ROS_INFO: Receiving: sEA LMDscandata 1
ROS_DEBUG: Starting scan data ....

[Info],2022-03-31 17:36:09.698,20788,Func 'thread_loop':
init_result:0
get_ip():192.168.1.100
get_port():2111
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> Succeeded in rebooting.

Current time:[Info],2022-03-31 17:36:09.907,20788,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:09.907,20788,Func 'set_looping_state':
New state is '1'
[Info],2022-03-31 17:36:09.907,20788,Func 'set_looping_state' end.
[Info],2022-03-31 17:36:09.907,5492,Func 'open':
New looping state:1
[Info],2022-03-31 17:36:09.907,5492,Func 'open' end.
[Info],2022-03-31 17:36:09.907,5492,Func 'reboot':
The result of 'open()' is true
[Info],2022-03-31 17:36:09.907,5492,Func 'reboot' end.
35
=====> frame index: 1 grab_time: 1.64872e+12ms time_gap: 5
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 2 grab_time: 1.64872e+12ms time_gap: 14
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 3 grab_time: 1.64872e+12ms time_gap: 4
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 4 grab_time: 1.64872e+12ms time_gap: 12
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 5 grab_time: 1.64872e+12ms time_gap: 21
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 6 grab_time: 1.64872e+12ms time_gap: 31
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 7 grab_time: 1.64872e+12ms time_gap: 38
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 8 grab_time: 1.64872e+12ms time_gap: 43
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 9 grab_time: 1.64872e+12ms time_gap: 47
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 10 grab_time: 1.64872e+12ms time_gap: 53
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 11 grab_time: 1.64872e+12ms time_gap: 58
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> Start to reboot.
Func 'reboot':
Start to run 'close()'.[Info],2022-03-31 17:36:10.695,5492,Func 'reboot' start.
[Info],2022-03-31 17:36:10.695,5492,Func 'reboot':
Start to run 'close()'.
[Info],2022-03-31 17:36:10.695,5492,Func 'close' start.
[Info],2022-03-31 17:36:10.695,5492,Func 'close':
Current state is 'LOOP_STATE::RUNNING'.
[Info],2022-03-31 17:36:10.695,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:10.695,5492,Func 'set_looping_state':
New state is '2'
[Info],2022-03-31 17:36:10.695,5492,Func 'set_looping_state' end.
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
[Info],2022-03-31 17:36:10.702,20788,Func 'thread_loop':
Outside loop, start to stop sock.

SOPAS - Stopped streaming scan data.
aaa.[Info],2022-03-31 17:36:10.713,20788,Func 'thread_loop':
stopScanData() finished
[Info],2022-03-31 17:36:10.713,20788,Func 'thread_loop':
End stopping sock.
[Info],2022-03-31 17:36:10.713,20788,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:10.713,20788,Func 'set_looping_state':
New state is '3'
[Info],2022-03-31 17:36:10.713,20788,Func 'set_looping_state' end.
ROS_WARN: Disconnecting TCP-Connection.
ERROR: Tcp::readInputData: Failed to read data from socket, aborting!
sick_scan driver exiting.
[Info],2022-03-31 17:36:10.713,20788,Func 'thread_loop' end.
[Info],2022-03-31 17:36:10.716,5492,Func 'close' end.
[Info],2022-03-31 17:36:10.716,5492,Func 'reboot':
Finished running 'close()'.
[Info],2022-03-31 17:36:11.718,5492,Func 'reboot':
Change port from 2111 to 2112
[Info],2022-03-31 17:36:11.718,5492,Func 'reboot':
Start to run 'open()'.
ROS_INFO: Publishing laserscan-pointcloud2 to
[Info],2022-03-31 17:36:11.718,5492,Func 'open' start.
[Info],2022-03-31 17:36:11.718,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:11.718,5492,Func 'set_looping_state':
New state is '0'
[Info],2022-03-31 17:36:11.718,5492,Func 'set_looping_state' end.
[Info],2022-03-31 17:36:11.718,16132,Func 'thread_loop' start.
[Info],2022-03-31 17:36:11.721,16132,Func 'thread_loop':
Start to run 'sock->init()'.
ROS_INFO: Parameter setting for <active_echo: 0>
ROS_DEBUG: Command: sMN SetAccessMode 3 F4724744
ROS_INFO: Sending : sMN SetAccessMode 3 F4724744
ROS_INFO: Receiving: sAN SetAccessMode 1
ROS_DEBUG: Command: sWN EIHstCola 0
ROS_INFO: Sending : sWN EIHstCola 0
ROS_INFO: Receiving: sWA EIHstCola
ROS_DEBUG: Command: sRN FirmwareVersion
ROS_INFO: Sending : sRN FirmwareVersion
ROS_INFO: Receiving: sRA FirmwareVersion 5 V2.61
ROS_DEBUG: Command: sRN SCdevicestate
ROS_INFO: Sending : sRN SCdevicestate
ROS_INFO: Receiving: sRA SCdevicestate 0
ROS_DEBUG: Laser is busy
ROS_DEBUG: Command: sRN ODoprh
ROS_INFO: Sending : sRN ODoprh
ROS_INFO: Receiving: sRA ODoprh 6B1A
ROS_DEBUG: Command: sRN ODpwrc
ROS_INFO: Sending : sRN ODpwrc
ROS_INFO: Receiving: sRA ODpwrc 32
ROS_DEBUG: Command: sRN LocationName
ROS_INFO: Sending : sRN LocationName
ROS_INFO: Receiving: sRA LocationName B not defined
ROS_INFO: Sending : sRN LMPoutputRange
ROS_INFO: Receiving: sRA LMPoutputRange 1 D05 FFF92230 225510
ROS_INFO: Angle resolution of scanner is 0.33330 [deg] (in 1/10000th deg: 0xD05)
ROS_INFO: [From:To] -45.00000 [deg] to 225.00000 [deg] (in 1/10000th deg: from 0xFFF92230 to 0x225510)
ROS_INFO: MIN_ANG: -2.356 [rad] -135.000 [deg]
ROS_INFO: MAX_ANG: 2.356 [rad] 135.000 [deg]
ROS_INFO: Sending : sWN LMPoutputRange 1 D05 FFF92230 225510 D05 FFF92230 225510 D05 FFF92230 225510 D05 FFF92230 225510
ROS_INFO: Receiving: sWA LMPoutputRange
ROS_INFO: Sending : sRN LMPoutputRange
ROS_INFO: Receiving: sRA LMPoutputRange 1 D05 FFF92230 225510
ROS_INFO: Angle resolution of scanner is 0.33330 [deg] (in 1/10000th deg: 0xD05)
ROS_INFO: MIN_ANG (after command verification): -2.356 [rad] -135.000 [deg]
ROS_INFO: MAX_ANG (after command verification): 2.356 [rad] 135.000 [deg]
ROS_INFO: Sending : sWN LMDscandatacfg 01 00 0 0 0 0 00 0 0 0 1 1
ROS_INFO: Receiving: sWA LMDscandatacfg
ROS_INFO: Sending : sRN LMDscandatacfg
ROS_INFO: Receiving: sRA LMDscandatacfg 1 0 0 0 0 0 0 0 0 0 1 1
ROS_DEBUG: Command: sMN LMCstartmeas
ROS_INFO: Sending : sMN LMCstartmeas
ROS_INFO: Receiving: sAN LMCstartmeas 0
ROS_DEBUG: Command: sMN Run
ROS_INFO: Sending : sMN Run
ROS_INFO: Receiving: sAN Run 1
ROS_DEBUG: Command: sEN LMDscandata 1
ROS_INFO: Sending : sEN LMDscandata 1
ROS_INFO: Receiving: sEA LMDscandata 1
ROS_DEBUG: Starting scan data ....

[Info],2022-03-31 17:36:12.114,16132,Func 'thread_loop':
init_result:0
get_ip():192.168.1.100
get_port():2112
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
[Info],2022-03-31 17:36:12.302,16132,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:12.302,16132,Func 'set_looping_state':
New state is '1'
[Info],2022-03-31 17:36:12.302,16132,Func 'set_looping_state' end.
[Info],2022-03-31 17:36:12.302,5492,Func 'open':
New looping state:1
=====> Succeeded in rebooting.

Current time:38
=====> frame index: 1 grab_time: 1.64872e+12ms time_gap: 2
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 2 grab_time: 1.64872e+12ms time_gap: 9
[Info],2022-03-31 17:36:12.302,5492,Func 'open' end.
[Info],2022-03-31 17:36:12.302,5492,Func 'reboot':
The result of 'open()' is true
[Info],2022-03-31 17:36:12.302,5492,Func 'reboot' end.
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 4 grab_time: 1.64872e+12ms time_gap: 42
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 5 grab_time: 1.64872e+12ms time_gap: 47
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
ROS_INFO: PANIC: Can not open ..\demo\scan.jpg_tmp for writing. Check existience of demo dir. or patch code.

ROS_INFO: PANIC: Can not open ..\demo\scan.csv_tmp for writing. Check existience of demo dir. or patch code.

=====> frame index: 6 grab_time: 1.64872e+12ms time_gap: 53
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 7 grab_time: 1.64872e+12ms time_gap: 58
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> Start to reboot.
Func 'reboot':
Start to run 'close()'.[Info],2022-03-31 17:36:13.096,5492,Func 'reboot' start.
[Info],2022-03-31 17:36:13.096,5492,Func 'reboot':
Start to run 'close()'.
[Info],2022-03-31 17:36:13.096,5492,Func 'close' start.
[Info],2022-03-31 17:36:13.096,5492,Func 'close':
Current state is 'LOOP_STATE::RUNNING'.
[Info],2022-03-31 17:36:13.096,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:13.096,5492,Func 'set_looping_state':
New state is '2'
[Info],2022-03-31 17:36:13.096,5492,Func 'set_looping_state' end.
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
[Info],2022-03-31 17:36:13.099,16132,Func 'thread_loop':
Outside loop, start to stop sock.

SOPAS - Stopped streaming scan data.
aaa.[Info],2022-03-31 17:36:13.110,16132,Func 'thread_loop':
stopScanData() finished
[Info],2022-03-31 17:36:13.110,16132,Func 'thread_loop':
End stopping sock.
[Info],2022-03-31 17:36:13.110,16132,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:13.110,16132,Func 'set_looping_state':
New state is '3'
[Info],2022-03-31 17:36:13.110,16132,Func 'set_looping_state' end.
ROS_WARN: Disconnecting TCP-Connection.
ERROR: Tcp::readInputData: Failed to read data from socket, aborting!
sick_scan driver exiting.
[Info],2022-03-31 17:36:13.111,16132,Func 'thread_loop' end.
[Info],2022-03-31 17:36:13.116,5492,Func 'close' end.
[Info],2022-03-31 17:36:13.116,5492,Func 'reboot':
Finished running 'close()'.
[Info],2022-03-31 17:36:14.118,5492,Func 'reboot':
Change port from 2112 to 2111
[Info],2022-03-31 17:36:14.118,5492,Func 'reboot':
Start to run 'open()'.
[Info],2022-03-31 17:36:14.118,5492,Func 'open' start.
[Info],2022-03-31 17:36:14.118,5492,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:14.118,5492,Func 'set_looping_state':
New state is '0'
[Info],2022-03-31 17:36:14.118,5492,Func 'set_looping_state' end.
[Info],2022-03-31 17:36:14.120,22700,Func 'thread_loop' start.
ROS_INFO: Publishing laserscan-pointcloud2 to
[Info],2022-03-31 17:36:14.121,22700,Func 'thread_loop':
Start to run 'sock->init()'.
ROS_INFO: Parameter setting for <active_echo: 0>
ROS_DEBUG: Command: sMN SetAccessMode 3 F4724744
ROS_INFO: Sending : sMN SetAccessMode 3 F4724744
ROS_INFO: Receiving: sAN SetAccessMode 1
ROS_DEBUG: Command: sWN EIHstCola 0
ROS_INFO: Sending : sWN EIHstCola 0
ROS_INFO: Receiving: sWA EIHstCola
ROS_DEBUG: Command: sRN FirmwareVersion
ROS_INFO: Sending : sRN FirmwareVersion
ROS_INFO: Receiving: sRA FirmwareVersion 5 V2.61
ROS_DEBUG: Command: sRN SCdevicestate
ROS_INFO: Sending : sRN SCdevicestate
ROS_INFO: Receiving: sRA SCdevicestate 0
ROS_DEBUG: Laser is busy
ROS_DEBUG: Command: sRN ODoprh
ROS_INFO: Sending : sRN ODoprh
ROS_INFO: Receiving: sRA ODoprh 6B1A
ROS_DEBUG: Command: sRN ODpwrc
ROS_INFO: Sending : sRN ODpwrc
ROS_INFO: Receiving: sRA ODpwrc 32
ROS_DEBUG: Command: sRN LocationName
ROS_INFO: Sending : sRN LocationName
ROS_INFO: Receiving: sRA LocationName B not defined
ROS_INFO: Sending : sRN LMPoutputRange
ROS_INFO: Receiving: sRA LMPoutputRange 1 D05 FFF92230 225510
ROS_INFO: Angle resolution of scanner is 0.33330 [deg] (in 1/10000th deg: 0xD05)
ROS_INFO: [From:To] -45.00000 [deg] to 225.00000 [deg] (in 1/10000th deg: from 0xFFF92230 to 0x225510)
ROS_INFO: MIN_ANG: -2.356 [rad] -135.000 [deg]
ROS_INFO: MAX_ANG: 2.356 [rad] 135.000 [deg]
ROS_INFO: Sending : sWN LMPoutputRange 1 D05 FFF92230 225510 D05 FFF92230 225510 D05 FFF92230 225510 D05 FFF92230 225510
ROS_INFO: Receiving: sWA LMPoutputRange
ROS_INFO: Sending : sRN LMPoutputRange
ROS_INFO: Receiving: sRA LMPoutputRange 1 D05 FFF92230 225510
ROS_INFO: Angle resolution of scanner is 0.33330 [deg] (in 1/10000th deg: 0xD05)
ROS_INFO: MIN_ANG (after command verification): -2.356 [rad] -135.000 [deg]
ROS_INFO: MAX_ANG (after command verification): 2.356 [rad] 135.000 [deg]
ROS_INFO: Sending : sWN LMDscandatacfg 01 00 0 0 0 0 00 0 0 0 1 1
ROS_INFO: Receiving: sWA LMDscandatacfg
ROS_INFO: Sending : sRN LMDscandatacfg
ROS_INFO: Receiving: sRA LMDscandatacfg 1 0 0 0 0 0 0 0 0 0 1 1
ROS_DEBUG: Command: sMN LMCstartmeas
ROS_INFO: Sending : sMN LMCstartmeas
ROS_INFO: Receiving: sAN LMCstartmeas 0
ROS_DEBUG: Command: sMN Run
ROS_INFO: Sending : sMN Run
ROS_INFO: Receiving: sAN Run 1
ROS_DEBUG: Command: sEN LMDscandata 1
ROS_INFO: Sending : sEN LMDscandata 1
ROS_INFO: Receiving: sEA LMDscandata 1
ROS_DEBUG: Starting scan data ....

[Info],2022-03-31 17:36:14.492,22700,Func 'thread_loop':
init_result:0
get_ip():192.168.1.100
get_port():2111
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> Succeeded in rebooting.

Current time:40[Info],2022-03-31 17:36:14.703,22700,Func 'set_looping_state' start.
[Info],2022-03-31 17:36:14.703,22700,Func 'set_looping_state':
New state is '1'
[Info],2022-03-31 17:36:14.703,22700,Func 'set_looping_state' end.
[Info],2022-03-31 17:36:14.703,5492,Func 'open':
New looping state:1
[Info],2022-03-31 17:36:14.703,5492,Func 'open' end.
[Info],2022-03-31 17:36:14.703,5492,Func 'reboot':
The result of 'open()' is true
[Info],2022-03-31 17:36:14.703,5492,Func 'reboot' end.

=====> frame index: 1 grab_time: 1.64872e+12ms time_gap: 2
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 2 grab_time: 1.64872e+12ms time_gap: 11
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 3 grab_time: 1.64872e+12ms time_gap: 14
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 4 grab_time: 1.64872e+12ms time_gap: 19
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 5 grab_time: 1.64872e+12ms time_gap: 25
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 6 grab_time: 1.64872e+12ms time_gap: 31
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 7 grab_time: 1.64872e+12ms time_gap: 35
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> frame index: 8 grab_time: 1.64872e+12ms time_gap: 41
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:

@rostest
Copy link
Collaborator

rostest commented Apr 1, 2022

Thanks for the log messages. The messages show some anomalies:

  • After start (initially or after restart), the scanner and driver seem to work as expected. But during receiving and handling of scan data, an unexpected reboot is called: 
    ROS_DEBUG: Starting scan data ....
ROS_DEBUG: Number of data: 811
MSG received...PUBLISH_DATA:
=====> Start to reboot.

In case of driver or lidar issues, the driver displays further error messages before restarting. The message "=====> Start to reboot" is not part of sick_scan_base. Could it be possible that a restart is triggered erroneously from an external source? At a first glance, scanner and driver work normally and there is no obvious reason to restart the scanner. Can you check what triggers this "=====> Start to reboot" message?

  • After restart, the driver fails to receive scanner data. After the next restart, the SOPAS mode has changed: 
    ERROR: Tcp::readInputData: Failed to read data from socket, aborting!
ROS_WARN: Timeout during waiting for new datagram
no answer received after 500 ms. Maybe sopas mode is wrong.
ROS_INFO: SOPAS Communication -Error unexpected Sopas Answer for request sMN SetAccessMode 3 F4724744
Waiting for timeout...
If the communication mode set in the scanner memory is different from that used by the driver, the scanner's communication mode is changed.
This requires a restart of the TCP-IP connection, which can extend the start time by up to 30 seconds. There are two ways to prevent this:
[Recommended] Set the communication mode with the SOPAS ET software to binary and save this setting in the scanner's EEPROM.
Use the parameter "use_binary_protocol" to overwrite the default settings of the driver.

A change in the SOPAS mode from binary to ascii communication normally happens after the scanner had been restarted. Maybe the scanner restarted due to network problems or a weak power supply?
We recommend configuring the binary SOPAS mode permanently using SOPAS ET, storing the settings in the scanner EEPROM and to configure <param name="use_binary_protocol" type="bool" value="true" /> in the launch file.

  • For demonstration purposes, the scan data are written to a jpg-file. The error message ROS_INFO: PANIC: Can not open ..\demo\scan.jpg_tmp for writing. Check existience of demo dir. or patch code. indicates a file access issue. Maybe the file is locked by another process?

Independent of this, writing jpg-files is for demonstration only. We recommend replacing this kind of pointcloud handling by a customized function.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@rostest @ceezous