시스템 로그 항목이 순서를 잃습니다.

시스템 로그 항목이 순서를 잃습니다.

Yocto Poky를 사용하여 완전히 자체 교차 컴파일된 임베디드 Linux 설치가 있습니다.

많은 시스템 서비스 외에도 헤드리스 데몬으로 실행되는 완전히 사용자 정의된 애플리케이션이 있습니다.

중요한 경우 애플리케이션은 전적으로 C++로 작성됩니다.

무슨 일이 일어나고 있는지에 대한 정보를 제공하기 위해 애플리케이션은 일반적 syslog()으로 적절한 매개변수를 사용하여 호출합니다.

이것~인 것 같다작동하지만 /var/log/messages를 면밀히 조사해 보면 로그 블록이 완전히 잘못된 순서로 도착하여 몇 분 내에 "뒤로 돌아오는" 것을 알 수 있습니다.

구체적으로 말하면, 매 100ms마다 시퀀스 번호(엄격히 증가하는 카운터, 매우 어리석은 코드)를 기록하는 작업이 있습니다.

타임스탬프와 시퀀스 번호는 동기화된 것처럼 보이지만(예: 연속된 시퀀스 번호는 거의 정확히 100ms 떨어져 있고 드리프트는 멀티스레딩 지연과 완전히 호환됨) 블록이 "스크램블링"되어 표시됩니다. 이는 일부 큰(몇 분) 약 1,000개의 메시지) 블록은 소위 "이전" 블록이라고 불리는 다른 블록 "뒤에" 나타날 수 있습니다.

이 설명이 문제를 이해하기에 "충분하지 않은" 경우 알려주십시오.

다음은 작은 (편집된) 발췌입니다:

-----------------------------------------------------------------------------------------------------------
    Jan 18 20:38:23 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:38:23.501] [D] [1794] pushBleMessage():Save a STATUS message [63308] to cache
    Jan 18 20:38:23 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:38:23.601] [D] [1794] pushBleMessage():Save a STATUS message [63309] to cache
    Jan 18 20:38:23 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:38:23.701] [D] [1794] pushBleMessage():Save a STATUS message [63310] to cache
    Jan 18 20:38:23 sa2150p-nand local0.info spoke-mw: [2022-01-18 20:38:23.804] [I] [1794] analyzeState():Start logging ego and other road users data
    Jan 18 20:38:23 sa2150p-nand local0.info spoke-mw: [2022-01-18 20:38:23.804] [I] [1794] analyzeState():[CV2X EGO  ] [   1642538303803ms] ID: 0000000000000001 long: 12.365475, lat: 41.939606, heading: 0.000000, speed: 0.000000, s_accur: 0.570000, acc: -0.000000
<<< jump back 224.337 seconds ***
    Jan 18 20:34:39 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:34:39.467] [D] [1794] pushBleMessage():Save a STATUS message [61072] to cache
    Jan 18 20:34:39 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:34:39.567] [D] [1794] pushBleMessage():Save a STATUS message [61073] to cache
    Jan 18 20:34:39 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:34:39.667] [D] [1794] pushBleMessage():Save a STATUS message [61074] to cache
    Jan 18 20:34:39 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:34:39.767] [D] [1794] pushBleMessage():Save a STATUS message [61075] to cache
    Jan 18 20:34:39 sa2150p-nand local0.info spoke-mw: [2022-01-18 20:34:39.867] [I] [1794] analyzeState():Start logging ego and other road users data
-----------------------------------------------------------------------------------------------------------
    Jan 18 20:36:31 sa2150p-nand local0.warn spoke-mw: [2022-01-18 20:36:31.400] [W] [1795] waitingConnection():No connection attempts for longer than 5000 ms
    Jan 18 20:36:31 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:36:31.400] [D] [1795] onRunBluetoothLoop():No BLE client yet. Retry after 1 second
    Jan 18 20:36:31 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:36:31.488] [D] [1794] pushBleMessage():Save a STATUS message [62190] to cache
    Jan 18 20:36:31 sa2150p-nand local0.info spoke-mw: [2022-01-18 20:36:31.588] [I] [1794] analyzeState():Start logging ego and other road users data
    Jan 18 20:36:31 sa2150p-nand local0.info spoke-mw: [2022-01-18 20:36:31.588] [I] [1794] analyzeState():[CV2X EGO  ] [   1642538191588ms] ID: 0000000000000001 long: 12.365476, lat: 41.939607, heading: 0.000000, speed: 0.000000, s_accur: 0.460000, acc: -0.000000
<<< jump back 224.151 seconds ***
    Jan 18 20:32:47 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:32:47.437] [D] [1794] pushBleMessage():Save a STATUS message [59954] to cache
    Jan 18 20:32:47 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:32:47.538] [D] [1794] pushBleMessage():Save a STATUS message [59955] to cache
    Jan 18 20:32:47 sa2150p-nand local0.info spoke-mw: [2022-01-18 20:32:47.638] [I] [1794] analyzeState():Start logging ego and other road users data
    Jan 18 20:32:47 sa2150p-nand local0.info spoke-mw: [2022-01-18 20:32:47.638] [I] [1794] analyzeState():[CV2X EGO  ] [   1642537967638ms] ID: 0000000000000001 long: 12.365478, lat: 41.939608, heading: 0.000000, speed: 0.000000, s_accur: 0.460000, acc: -0.000000
    Jan 18 20:32:47 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:32:47.638] [D] [1794] pushBleMessage():Save a STATUS message [59956] to cache
-----------------------------------------------------------------------------------------------------------
    Jan 18 20:34:39 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:34:39.166] [D] [1794] pushBleMessage():Save a STATUS message [61069] to cache
    Jan 18 20:34:39 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:34:39.266] [D] [1794] pushBleMessage():Save a STATUS message [61070] to cache
    Jan 18 20:34:39 sa2150p-nand local0.info spoke-mw: [2022-01-18 20:34:39.366] [I] [1794] analyzeState():Start logging ego and other road users data
    Jan 18 20:34:39 sa2150p-nand local0.info spoke-mw: [2022-01-18 20:34:39.367] [I] [1794] analyzeState():[CV2X EGO  ] [   1642538079367ms] ID: 0000000000000001 long: 12.365477, lat: 41.939608, heading: 0.000000, speed: 0.000000, s_accur: 0.450000, acc: -0.000000
    Jan 18 20:34:39 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:34:39.367] [D] [1794] pushBleMessage():Save a STATUS message [61071] to cache
<<< jump back 224.036 seconds ***
    Jan 18 20:30:55 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:30:55.331] [D] [1794] pushBleMessage():Save a STATUS message [58835] to cache
    Jan 18 20:30:55 sa2150p-nand local0.info spoke-mw: [2022-01-18 20:30:55.431] [I] [1794] analyzeState():Start logging ego and other road users data
    Jan 18 20:30:55 sa2150p-nand local0.info spoke-mw: [2022-01-18 20:30:55.431] [I] [1794] analyzeState():[CV2X EGO  ] [   1642537855431ms] ID: 0000000000000001 long: 12.365479, lat: 41.939608, heading: 0.000000, speed: 0.000000, s_accur: 0.450000, acc: -0.000000
    Jan 18 20:30:55 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:30:55.431] [D] [1794] pushBleMessage():Save a STATUS message [58836] to cache
    Jan 18 20:30:55 sa2150p-nand local0.debug spoke-mw: [2022-01-18 20:30:55.531] [D] [1794] pushBleMessage():Save a STATUS message [58837] to cache
-----------------------------------------------------------------------------------------------------------

메시지는 Save a STATUS message [61069/70/71] to cache훨씬 나중에 나타나는 Save a STATUS message [61072/73/..] to cache반면 스탬프는 상당히 좋은 순서를 따릅니다.

그것~인 것 같다문제는 전적으로 syslog()처리에 관한 것이며, 인터넷 검색에서도 비슷한 동작의 흔적을 찾았지만 이것이 제 경우에도 적용되는지 잘 모르겠습니다.

문제는 이 상황을 어떻게 디버깅할 것인가입니다. "순서가 잘못된 로그"를 갖는 것은 아무리 말해도 "불편합니다".

관련 정보