Race condition starting new binary log #35

Closed
jmthomas opened this Issue Feb 2, 2015 · 7 comments

Comments

Projects
None yet
2 participants
@jmthomas
Member

jmthomas commented Feb 2, 2015

I've seen COSMOS occasionally open a log file, immediately close it, and then open another log file with the '_1.bin' extension. Seems like there is a rare race condition when starting a new log file that causes it to be closed and another opened.

@jmthomas jmthomas added the bug label Feb 2, 2015

@ryanatball

This comment has been minimized.

Show comment
Hide comment
@ryanatball

ryanatball Feb 2, 2015

Member

I don't thnk there is a race condition within packet_log_writer. There may be somewhere in the code where close is being called twice within same second. Are you only seeing this at shutdown?

Member

ryanatball commented Feb 2, 2015

I don't thnk there is a race condition within packet_log_writer. There may be somewhere in the code where close is being called twice within same second. Are you only seeing this at shutdown?

@ryanatball ryanatball added question and removed bug labels Feb 2, 2015

@jmthomas

This comment has been minimized.

Show comment
Hide comment
@jmthomas

jmthomas Feb 2, 2015

Member

Unfortunately no it was during normal running. I'll dig up the server log messages for that time period.

Question label?

Member

jmthomas commented Feb 2, 2015

Unfortunately no it was during normal running. I'll dig up the server log messages for that time period.

Question label?

@ryanatball

This comment has been minimized.

Show comment
Hide comment
@ryanatball

ryanatball Feb 2, 2015

Member

:) Question label is just because I'm not sure this is an actual bug or not.

Member

ryanatball commented Feb 2, 2015

:) Question label is just because I'm not sure this is an actual bug or not.

@ryanatball ryanatball added possible bug and removed question labels Feb 2, 2015

@jmthomas

This comment has been minimized.

Show comment
Hide comment
@jmthomas

jmthomas Feb 3, 2015

Member

I found several instances of this occurring in the sever message log. The signature is basically this:

2015/02/02 16:35:58.088  INFO: Log File Opened : 2015_02_02_16_35_58_tlm.bin
2015/02/02 16:35:58.089  INFO: Log File Closed : 2015_02_02_16_35_58_tlm.bin
2015/02/02 16:35:58.090  INFO: Log File Opened : 2015_02_02_16_35_58_tlm_1.bin

When I open the first file it always has just a single packet in it. I've had this happen with both command and telemetry logs. Frequency seems to be about once a day although it's a bit sporadic.

I have 7 loggers which are all basically setup as follows:

PACKET_LOG_WRITER DEFAULT meta_packet_log_writer.rb COSMOS META config/data/default_meta_pri.txt true true cosmos true 600
Member

jmthomas commented Feb 3, 2015

I found several instances of this occurring in the sever message log. The signature is basically this:

2015/02/02 16:35:58.088  INFO: Log File Opened : 2015_02_02_16_35_58_tlm.bin
2015/02/02 16:35:58.089  INFO: Log File Closed : 2015_02_02_16_35_58_tlm.bin
2015/02/02 16:35:58.090  INFO: Log File Opened : 2015_02_02_16_35_58_tlm_1.bin

When I open the first file it always has just a single packet in it. I've had this happen with both command and telemetry logs. Frequency seems to be about once a day although it's a bit sporadic.

I have 7 loggers which are all basically setup as follows:

PACKET_LOG_WRITER DEFAULT meta_packet_log_writer.rb COSMOS META config/data/default_meta_pri.txt true true cosmos true 600
@ryanatball

This comment has been minimized.

Show comment
Hide comment
@ryanatball

ryanatball Feb 3, 2015

Member

Is there another "Log File Closed" line immediately before your first "Log File Opened" ?

Member

ryanatball commented Feb 3, 2015

Is there another "Log File Closed" line immediately before your first "Log File Opened" ?

@jmthomas

This comment has been minimized.

Show comment
Hide comment
@jmthomas

jmthomas Feb 3, 2015

Member

In most cases the last log file was closed 2s or so before. However in one command log it was closed 2 hours before.

Member

jmthomas commented Feb 3, 2015

In most cases the last log file was closed 2s or so before. However in one command log it was closed 2 hours before.

@ryanatball

This comment has been minimized.

Show comment
Hide comment
@ryanatball

ryanatball Feb 3, 2015

Member

Ok I see the problem. Fix in a minute.

Member

ryanatball commented Feb 3, 2015

Ok I see the problem. Fix in a minute.

@ryanatball ryanatball added bug and removed possible bug labels Feb 3, 2015

@ryanatball ryanatball closed this in #42 Feb 3, 2015

ryanatball added a commit that referenced this issue Feb 3, 2015

Merge pull request #42 from BallAerospace/bugfix/35-race-condition-st…
…arting-new-log


closes #35 - Take Mutex in Cycle Thread

@ryanatball ryanatball added this to the v3.1.2 milestone Feb 20, 2015

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment