JP7FKFの備忘録

ヒトは,忘れる生き物だから.

STM32でSWCLK, SWDIOをGPIO Outputにして書き込めずにハマる

STM32でSWCLK, SWDIOをGPIOとしてoutputに使ったとき.

  • いつもどおりflashからbootすると,起動直後にGPIOがoutになってしまってそのままでは書き込めなくなる.
  • いったんBOOT0をHighにしてシステムメモリor RAM起動にするとから書き込むと書き込める.
    • BOOT0の状態BOOT1=Highならシステムメモリ,LowならRAM boot.
    • BOOT0=Lowだとflash bootだからね.

References

STM32 HAL GPIOの基礎の基礎

おことわり・前提

  • STM32CubeIDEを使った話をします.
  • あくまで自分用のメモという目的が主.
  • 逐次updateしたり追記したりがあるかもしれません.

本題

#define LCD_RS_Pin GPIO_PIN_6
#define LCD_RS_GPIO_Port GPIOA
  • エイリアスの先はちゃんとdriverのheaderで定義されている.なのでlabelをつけたからといってGPIOAGPIO_PIN_Xなどで指定できなくなるというわけではない.
    • ./Drivers/STM32F0xx_HAL_Driver/Inc/stm32f0xx_hal_gpio.h
...(snip)...
/* Exported constants --------------------------------------------------------*/
/** @defgroup GPIO_Exported_Constants GPIO Exported Constants
  * @{
  */
/** @defgroup GPIO_pins GPIO pins
  * @{
  */
#define GPIO_PIN_0                 ((uint16_t)0x0001U)  /* Pin 0 selected    */
#define GPIO_PIN_1                 ((uint16_t)0x0002U)  /* Pin 1 selected    */
#define GPIO_PIN_2                 ((uint16_t)0x0004U)  /* Pin 2 selected    */
#define GPIO_PIN_3                 ((uint16_t)0x0008U)  /* Pin 3 selected    */
#define GPIO_PIN_4                 ((uint16_t)0x0010U)  /* Pin 4 selected    */
#define GPIO_PIN_5                 ((uint16_t)0x0020U)  /* Pin 5 selected    */
#define GPIO_PIN_6                 ((uint16_t)0x0040U)  /* Pin 6 selected    */
#define GPIO_PIN_7                 ((uint16_t)0x0080U)  /* Pin 7 selected    */
#define GPIO_PIN_8                 ((uint16_t)0x0100U)  /* Pin 8 selected    */
#define GPIO_PIN_9                 ((uint16_t)0x0200U)  /* Pin 9 selected    */
#define GPIO_PIN_10                ((uint16_t)0x0400U)  /* Pin 10 selected   */
#define GPIO_PIN_11                ((uint16_t)0x0800U)  /* Pin 11 selected   */
#define GPIO_PIN_12                ((uint16_t)0x1000U)  /* Pin 12 selected   */
#define GPIO_PIN_13                ((uint16_t)0x2000U)  /* Pin 13 selected   */
#define GPIO_PIN_14                ((uint16_t)0x4000U)  /* Pin 14 selected   */
#define GPIO_PIN_15                ((uint16_t)0x8000U)  /* Pin 15 selected   */
#define GPIO_PIN_All               ((uint16_t)0xFFFFU)  /* All pins selected */
...(snip)...

STM32 HAL PWMの基礎の基礎

おことわり・前提

  • STM32CubeIDEを使った話をします.
  • あくまで自分用のメモという目的が主.
  • 逐次updateしたり追記したりがあるかもしれません.

本題

  • PWMを出すには
    • CubeMXで利用したいタイマを選択.channelの設定でどのピンをPWM出力として使うかを指定.
    • 普通のタイマの設定と同様にプリスケーラ,カウンタを設定.
    • cubeMXでgenerateされるコードはconfigまでは入るがそのままではPWMがstartしない.
      • HAL_TIM_PWM_Start();をcallする必要がある.MX_TIMx_Init()の最後で呼んでおくと良さそう.
      • 別にmainで利用時にstartするのでも問題ない.

コードを見ていく

/**
  * @brief TIM1 Initialization Function
  * @param None
  * @retval None
  */
static void MX_TIM1_Init(void)
{

  /* USER CODE BEGIN TIM1_Init 0 */

  /* USER CODE END TIM1_Init 0 */

  TIM_ClockConfigTypeDef sClockSourceConfig = {0};
  TIM_MasterConfigTypeDef sMasterConfig = {0};
  TIM_OC_InitTypeDef sConfigOC = {0};
  TIM_BreakDeadTimeConfigTypeDef sBreakDeadTimeConfig = {0};

  /* USER CODE BEGIN TIM1_Init 1 */

  /* USER CODE END TIM1_Init 1 */
  htim1.Instance = TIM1;
  htim1.Init.Prescaler = 9;
  htim1.Init.CounterMode = TIM_COUNTERMODE_UP;
  htim1.Init.Period = 799;
  htim1.Init.ClockDivision = TIM_CLOCKDIVISION_DIV1;
  htim1.Init.RepetitionCounter = 0;
  htim1.Init.AutoReloadPreload = TIM_AUTORELOAD_PRELOAD_ENABLE;
  if (HAL_TIM_Base_Init(&htim1) != HAL_OK)
  {
    Error_Handler();
  }
  sClockSourceConfig.ClockSource = TIM_CLOCKSOURCE_INTERNAL;
  if (HAL_TIM_ConfigClockSource(&htim1, &sClockSourceConfig) != HAL_OK)
  {
    Error_Handler();
  }
  if (HAL_TIM_PWM_Init(&htim1) != HAL_OK)
  {
    Error_Handler();
  }
  sMasterConfig.MasterOutputTrigger = TIM_TRGO_RESET;
  sMasterConfig.MasterSlaveMode = TIM_MASTERSLAVEMODE_DISABLE;
  if (HAL_TIMEx_MasterConfigSynchronization(&htim1, &sMasterConfig) != HAL_OK)
  {
    Error_Handler();
  }
  sConfigOC.OCMode = TIM_OCMODE_PWM1;
  sConfigOC.Pulse = 100;
  sConfigOC.OCPolarity = TIM_OCPOLARITY_HIGH;
  sConfigOC.OCNPolarity = TIM_OCNPOLARITY_HIGH;
  sConfigOC.OCFastMode = TIM_OCFAST_DISABLE;
  sConfigOC.OCIdleState = TIM_OCIDLESTATE_RESET;
  sConfigOC.OCNIdleState = TIM_OCNIDLESTATE_RESET;
  if (HAL_TIM_PWM_ConfigChannel(&htim1, &sConfigOC, TIM_CHANNEL_1) != HAL_OK)
  {
    Error_Handler();
  }
  sConfigOC.Pulse = (uint32_t)htim1.Init.Period*0.4;
  if (HAL_TIM_PWM_ConfigChannel(&htim1, &sConfigOC, TIM_CHANNEL_4) != HAL_OK)
  {
    Error_Handler();
  }
  sBreakDeadTimeConfig.OffStateRunMode = TIM_OSSR_DISABLE;
  sBreakDeadTimeConfig.OffStateIDLEMode = TIM_OSSI_DISABLE;
  sBreakDeadTimeConfig.LockLevel = TIM_LOCKLEVEL_OFF;
  sBreakDeadTimeConfig.DeadTime = 0;
  sBreakDeadTimeConfig.BreakState = TIM_BREAK_DISABLE;
  sBreakDeadTimeConfig.BreakPolarity = TIM_BREAKPOLARITY_HIGH;
  sBreakDeadTimeConfig.AutomaticOutput = TIM_AUTOMATICOUTPUT_DISABLE;
  if (HAL_TIMEx_ConfigBreakDeadTime(&htim1, &sBreakDeadTimeConfig) != HAL_OK)
  {
    Error_Handler();
  }
  /* USER CODE BEGIN TIM1_Init 2 */

  HAL_TIM_PWM_Start(&htim1, TIM_CHANNEL_1);
  HAL_TIM_PWM_Start(&htim1, TIM_CHANNEL_4);
  /* USER CODE END TIM1_Init 2 */
  HAL_TIM_MspPostInit(&htim1);

}
  • 例えばこんな関数を作っておくとdutyをtimer/channelごとに更新できる.
void setPWM(TIM_HandleTypeDef *htim, uint32_t Channel, float duty)
{
  TIM_OC_InitTypeDef sConfigOC = {0};

  sConfigOC.OCMode = TIM_OCMODE_PWM1;
  sConfigOC.Pulse = (uint32_t)htim1.Init.Period*duty;
  sConfigOC.OCPolarity = TIM_OCPOLARITY_HIGH;
  sConfigOC.OCNPolarity = TIM_OCNPOLARITY_HIGH;
  sConfigOC.OCFastMode = TIM_OCFAST_DISABLE;
  sConfigOC.OCIdleState = TIM_OCIDLESTATE_RESET;
  sConfigOC.OCNIdleState = TIM_OCNIDLESTATE_RESET;

  if (HAL_TIM_PWM_ConfigChannel(htim, &sConfigOC, Channel) != HAL_OK)
  {
    Error_Handler();
  }

  HAL_TIM_PWM_Start(htim, Channel);
}

STM32 HAL 外部割り込みの基礎の基礎

おことわり・前提

  • STM32CubeIDEを使った話をします.
  • あくまで自分用のメモという目的が主.
  • 逐次updateしたり追記したりがあるかもしれません.

本題

  • 外部割り込みをするには
    • GPIOをEXTI Interrupt modeにする. f:id:jp7fkf:20200603210148p:plain
    • NVICで該当のEXTI Interruptをenableにする. f:id:jp7fkf:20200603210153p:plain
      • これを忘れるとEXTIされないので注意.ハマりがち.
      • 外部割り込みに限らずなんだけれども,割り込みの優先順位は適切につける.
        • 例えば外部割り込みの中でHAL_Delay()を呼んだりしたいときはTime base: System tick timerより外部割り込みの優先順位を下げないと処理が戻ってこなかったりする.

実際のコードをみて割り込みの流れをみる

  • ./Core/Src/stm32f0xx_it.c
/******************************************************************************/
/* STM32F0xx Peripheral Interrupt Handlers                                    */
/* Add here the Interrupt Handlers for the used peripherals.                  */
/* For the available peripheral interrupt handler names,                      */
/* please refer to the startup file (startup_stm32f0xx.s).                    */
/******************************************************************************/

/**
  * @brief This function handles EXTI line 0 and 1 interrupts.
  */
void EXTI0_1_IRQHandler(void)
{
  /* USER CODE BEGIN EXTI0_1_IRQn 0 */

  /* USER CODE END EXTI0_1_IRQn 0 */
  HAL_GPIO_EXTI_IRQHandler(GPIO_PIN_1);
  /* USER CODE BEGIN EXTI0_1_IRQn 1 */

  /* USER CODE END EXTI0_1_IRQn 1 */
}
  • 複数のEXTIピンを定義した場合でも同じHAL_GPIO_EXTI_IRQHandler()がcallされる.
/******************************************************************************/
/* STM32F0xx Peripheral Interrupt Handlers                                    */
/* Add here the Interrupt Handlers for the used peripherals.                  */
/* For the available peripheral interrupt handler names,                      */
/* please refer to the startup file (startup_stm32f0xx.s).                    */
/******************************************************************************/

/**
  * @brief This function handles EXTI line 0 and 1 interrupts.
  */
void EXTI0_1_IRQHandler(void)
{
  /* USER CODE BEGIN EXTI0_1_IRQn 0 */

  /* USER CODE END EXTI0_1_IRQn 0 */
  HAL_GPIO_EXTI_IRQHandler(GPIO_PIN_1);
  /* USER CODE BEGIN EXTI0_1_IRQn 1 */

  /* USER CODE END EXTI0_1_IRQn 1 */
}

/**
  * @brief This function handles EXTI line 2 and 3 interrupts.
  */
void EXTI2_3_IRQHandler(void)
{
  /* USER CODE BEGIN EXTI2_3_IRQn 0 */

  /* USER CODE END EXTI2_3_IRQn 0 */
  HAL_GPIO_EXTI_IRQHandler(GPIO_PIN_3);
  /* USER CODE BEGIN EXTI2_3_IRQn 1 */

  /* USER CODE END EXTI2_3_IRQn 1 */
}
  • HAL_GPIO_EXTI_IRQHandler()がcallされると割り込みビットの処理が実行され,HAL_GPIO_EXTI_Callback()がcallされる.
    • これがユーザが実際に定義することを想定しているcallback functionである.
    • stm32f0xx_hal_gpio.cですでに__weak void HAL_GPIO_EXTI_Callback(uint16_t GPIO_Pin)という形で定義されているが,__weak指定子がついているので,ユーザがvoid HAL_GPIO_EXTI_Callback(uint16_t GPIO_Pin)を別で定義した場合それが優先される.
  • ./Drivers/STM32F0xx_HAL_Driver/Src/stm32f0xx_hal_gpio.c
/**
  * @brief  Handle EXTI interrupt request.
  * @param  GPIO_Pin Specifies the port pin connected to corresponding EXTI line.
  * @retval None
  */
void HAL_GPIO_EXTI_IRQHandler(uint16_t GPIO_Pin)
{
  /* EXTI line interrupt detected */
  if(__HAL_GPIO_EXTI_GET_IT(GPIO_Pin) != 0x00u)
  {
    __HAL_GPIO_EXTI_CLEAR_IT(GPIO_Pin);
    HAL_GPIO_EXTI_Callback(GPIO_Pin);
  }
}

/**
  * @brief  EXTI line detection callback.
  * @param  GPIO_Pin Specifies the port pin connected to corresponding EXTI line.
  * @retval None
  */
__weak void HAL_GPIO_EXTI_Callback(uint16_t GPIO_Pin)
{
  /* Prevent unused argument(s) compilation warning */
  UNUSED(GPIO_Pin);

  /* NOTE: This function should not be modified, when the callback is needed,
            the HAL_GPIO_EXTI_Callback could be implemented in the user file
   */
}
  • ユーザは実際にvoid HAL_GPIO_EXTI_Callback(uint16_t GPIO_Pin)を定義して利用することができる.
    • 引数としてGPIO_PINが渡されるので,これを見てどのピンのEXTI割り込みかを判断する.
void HAL_GPIO_EXTI_Callback(uint16_t GPIO_Pin){
  HAL_Delay(1);
  printf("EXTI callback called!\r\n");
  if (GPIO_Pin == GPIO_PIN_3)
    printf("gpio3 pushed!\r\n");
  if (GPIO_Pin == GPIO_PIN_1)
    printf("gpio1 released!\r\n");
}
  • STM32 external interrupt and tick timer - Programmer Soughte
    • EXTI内部でHAL_Delay()を叩くとすべての処理が停止することがあった.
    • これは割り込み優先度がすべて0となっていたため.
    • HAL_Delay()systickを利用するためこの割り込みの優先度をあげ,EXTI割り込みの優先度を下げる必要がある.
    • これにより無限ループによる処理停止が引き起こされない.

STM32 HAL ADCの基礎の基礎

おことわり・前提

  • STM32CubeIDEを使った話をします.
  • あくまで自分用のメモという目的が主.
  • 逐次updateしたり追記したりがあるかもしれません.

本題

  • DMAで連続変換するときの鍵

    • clockはsystem clock devidedなものを入れると楽.Async clockは別途記述が必要.
    • continuous conversion enableにしてDMA continuous request enableにしておくとDMA割り込みが入りまくることに注意.ADCが終わるたびにDMA走る.
      • これを防ぐにはcontinuous conversion disableとして普通にタイマ割り込みでADCを回すのが良さそう.DMA continuous requestはenableのまま.
    • DMAはcircularを選ぶ
    • DMAのmemory はincrementにしておく
    • DMA continuous request enable
    • 上記をやっておかないと連続変換されなかったり,DMAに連続的に変換結果が入らずにハマる.
      • もちろん理解して変更すればいいが,基本上記でいいかなぁという気持ち.
  • code examples

constexpr  adcChannels = 3; //number of using ADC channels
static uint16_t adcData[adcChannels];
if (HAL_ADC_Start_DMA(&hadc,(uint32_t *)adcData, adcChannels) != HAL_OK)
  Error_Handler();

これで逐次clockに応じてADCが動作しDMAで adcData[]に変換結果が転送される. 変換完了後にcallbackしたい場合は下記等が便利.変換完了時にcallbackされる.

void HAL_ADC_ConvCpltCallback(ADC_HandleTypeDef *AdcHandle){
  //do something
}
if(HAL_ADCEx_Calibration_Start(&hadc) != HAL_OK)
    Error_Handler();
  • タイマ割り込みにする場合

    • CubeMXでADCのconfigを下記のようにする.ADCのチャネル,DMA転送など基本的なconfigはできている前提で
      • ADC_Regular_ConversionMode->External Trigger Conversion SourceTimer1 Trigger Out eventに. f:id:jp7fkf:20200603210138p:plain
    • さらにCubeMXでTIM Timer1のconfigをする.プリスケーラやカウンタ値等のタイマ割り込みを発生させるconfigは書けている前提で
      • Trigger Output(TRGO) Parameters -> Trigger Event SelectionUpdate Eventに. f:id:jp7fkf:20200603210133p:plain これでタイマ割り込みでADCがトリガされるはず.
  • ADCのキャネルとデータの入り方 ch1, ch2, ch3, ch4, ch5, ch6, ch7 を有効にしていたとして

constexpr  adcChannels = 8; //number of using ADC channels
static uint16_t adcData[adcChannels];
if (HAL_ADC_Start_DMA(&hadc,(uint32_t *)adcData, adcChannels) != HAL_OK)
  Error_Handler();

このようなコードを書いた場合,変換結果は

ch1: adcData[0];
ch2: adcData[1];
ch3: adcData[2];
ch4: adcData[3];
ch5: adcData[4];
ch6: adcData[5];
ch7: adcData[6];
ch8: adcData[7];

に対応して格納される.

ch1, ch3, ch5, ch7を有効(ch2, ch4, ch6は無効)にしていたとして

constexpr  adcChannels = 4; //number of using ADC channels
static uint16_t adcData[adcChannels];
if (HAL_ADC_Start_DMA(&hadc,(uint32_t *)adcData, adcChannels) != HAL_OK)
  Error_Handler();

このようなコードを書くと

ch1: adcData[0];
ch3: adcData[1];
ch5: adcData[2];
ch7: adcData[3];

仮にここで

constexpr  adcChannels = 3; //number of using ADC channels

としてしまった場合,書くchの変換結果が同一の添字(配列index)で取得できなくなる.
具体的にはリングバッファのようにずれてしまう.
したがってHAL_ADC_Start_DMA()に渡すbufはchに対し十分余裕を持ちlengthは有効化しているadcチャネルと同一値とすることが大変重要である.
有効化しているadcチャネル数よりも少なくても多くてもずれが生じる.
この状態で気づかずに変換結果を取得すると逐次値が変動してハマる.ノイズのよう見見えてしまうことがあるかもしれない.
念の為adcの各chが同一の添字で同じものが取り続けられているかをserial(uart)等を利用し事前に確認しておくことが望ましい.

  • ちなみにプロトタイプはこんな感じになっている: HAL_StatusTypeDef HAL_ADC_Start_DMA(ADC_HandleTypeDef* hadc, uint32_t* pData, uint32_t Length)

zabbix-agentがmemory leakしていたのでZabbix communityにBug patch/reportを出してみた話

// ちなみのこのbugreportを出したのもmergeされたのももうしばらく前(2019年末から2020年頭)の話.

私は仕事でも趣味(?)でも,OSSの監視ツールであるZabbixに大変お世話になっている.
zabbixは主にネットワークやサーバなどのインフラに強みをもった監視ツールで,サーバならzabbix-agent, ネットワーク機器ならSNMPなどを主に用いて,各種ステータスやメトリクスの監視,可視化が行えるツールである.

先日このzabbixから一つのalertが飛んできた.アラート内容は available memory に関するアラート.これが何を意味するかと言うとつまり,空きメモリに余裕がないということである. グラフ波形を見る限り日を追うごとにメモリが少しずつ侵食されており,典型的なメモリリークの症状であった.また身の回りの他の人からも同様の症状があるという報告を得た. top/htop等を見てmemoryを専有するプロセスを探したところ zabbix-agentd と書かれたプロセスのメモリ使用率が著しく高いことがわかった. ここまでで,何らかの原因でzabbix-agentdがmemory leakしていることがわかった.

zabbixがOSSであることを知っていたため,私は原因を突き止め,デバッグし,まず自分の身の回りで生じているメモリリークによる影響を排除しようと考えた. また,まだreportが上がっていないのであればzabbixのOSS communityに対しbug patch/reportをあげ,自分自身が少しでも普段利用しているzabbixに貢献し,また同様のことで困っている方の助けに少しでもなれればうれしい,と考えた. 今回はその過程を少し記録しておく.

Root Causeの特定

top等のコマンドを用いて特定できるのはあくまでどのプロセスがメモリを専有しているか,という情報のみである.
ここからzabbix-agentdがメモリを大きく専有していることまではわかったが,ここからやるべきことは "zabbix-agentdのどこでこのメモリリークが生じているか" を確かめることである.
メモリリークを検出する方法はたくさんの手法があるが,今回の場合実行ファイルがあるだけで利用できるという点にメリットを感じて Valgrind を用いた.
Valgrindの詳細な動作については,私は理解していないが,おそらくはサンドボックス上でバイナリを実行し,その実行時に特にメモリを取り扱うシステムコール等をwrapすることでリーク等を検知できる仕組みが備わっているのではないかと思う.

zabbix-agentdをValgrindを食わせて実行した結果,次のような結果が得られた(一部抜粋).

==27583== HEAP SUMMARY:
==27583==     in use at exit: 109,825 bytes in 188 blocks
==27583==   total heap usage: 44,181 allocs, 43,993 frees, 4,111,671 bytes allocated
==27583==
==27583== 1 bytes in 1 blocks are definitely lost in loss record 1 of 38
==27583==    at 0x4C2FB0F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==27583==    by 0x162F4D: zbx_malloc2 (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x168C40: zbx_strncpy_alloc (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x168EA4: zbx_strcpy_alloc (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x13F420: VFS_FILE_CONTENTS (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x12C91C: process (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x128C9C: ??? (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x12911E: listener_thread (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x14FF44: zbx_thread_start (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x11A597: MAIN_ZABBIX_ENTRY (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x1516A7: daemon_start (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x11A9FA: main (in /usr/sbin/zabbix_agentd.orig)
==27583==
==27583== 98,304 bytes in 1 blocks are definitely lost in loss record 38 of 38
==27583==    at 0x4C31D2F: realloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==27583==    by 0x162FFC: zbx_realloc2 (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x168CC0: zbx_strncpy_alloc (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x168EA4: zbx_strcpy_alloc (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x13F420: VFS_FILE_CONTENTS (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x12C91C: process (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x128C9C: ??? (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x12911E: listener_thread (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x14FF44: zbx_thread_start (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x11A597: MAIN_ZABBIX_ENTRY (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x1516A7: daemon_start (in /usr/sbin/zabbix_agentd.orig)
==27583==    by 0x11A9FA: main (in /usr/sbin/zabbix_agentd.orig)
==27583==
==27583== LEAK SUMMARY:
==27583==    definitely lost: 98,305 bytes in 2 blocks
==27583==    indirectly lost: 0 bytes in 0 blocks
==27583==      possibly lost: 0 bytes in 0 blocks
==27583==    still reachable: 11,520 bytes in 186 blocks
==27583==         suppressed: 0 bytes in 0 blocks
==27583== Reachable blocks (those to which a pointer was found) are not shown.
==27583== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==27583==
==27583== For counts of detected and suppressed errors, rerun with: -v
==27583== Use --track-origins=yes to see where uninitialised values come from
==27583== ERROR SUMMARY: 592818 errors from 11 contexts (suppressed: 0 from 0)

1 bytes in 1 blocks are definitely lost in loss record 1 of 38 などの出力がみられる.
これはこの部分でmemory leakがある(具体的にはメモリへのポインタを失う)ことを示している.
続けて,lostしたと考えられる箇所が記述されている.

上記に示した2件ではどうやら zbx_strncpy_alloc() 内部で利用されているzbx_malloc2(), zbx_realloc2()で生じているように見受けられる.
ここのコードを見てみる.

void    zbx_strncpy_alloc(char **str, size_t *alloc_len, size_t *offset, const char *src, size_t n)
{
        if (NULL == *str)
        {
                *alloc_len = n + 1;
                *offset = 0;
                *str = (char *)zbx_malloc(*str, *alloc_len);
        }
        else if (*offset + n >= *alloc_len)
        {
                while (*offset + n >= *alloc_len)
                        *alloc_len *= 2;
                *str = (char *)zbx_realloc(*str, *alloc_len);
        }

        while (0 != n && '\0' != *src)
        {
                (*str)[(*offset)++] = *src++;
                n--;
        }

        (*str)[*offset] = '\0';
}

ref: zabbix/str.c at 4.4.5 · zabbix/zabbix · GitHub

内部でzbx_malloc()zbx_realloc()がcallされていることがわかる.この定義を見ると

#define zbx_calloc(old, nmemb, size)  zbx_calloc2(__FILE__, __LINE__, old, nmemb, size)
#define zbx_malloc(old, size)   zbx_malloc2(__FILE__, __LINE__, old, size)
#define zbx_realloc(src, size)    zbx_realloc2(__FILE__, __LINE__, src, size)
#define zbx_strdup(old, str)    zbx_strdup2(__FILE__, __LINE__, old, str)

ref:zabbix/common.h at b93f5c4fc09286ec199910c7d450b8a4bf4dd3de · zabbix/zabbix · GitHub

zbx_malloc2(), zbx_realloc2()がcallされる.これらをみてみると.

void  *zbx_malloc2(const char *filename, int line, void *old, size_t size)
{
  int max_attempts;
  void  *ptr = NULL;

  /* old pointer must be NULL */
  if (NULL != old)
  {
    zabbix_log(LOG_LEVEL_CRIT, "[file:%s,line:%d] zbx_malloc: allocating already allocated memory. "
        "Please report this to Zabbix developers.",
        filename, line);
  }

  for (
    max_attempts = 10, size = MAX(size, 1);
    0 < max_attempts && NULL == ptr;
    ptr = malloc(size), max_attempts--
  );

  if (NULL != ptr)
    return ptr;

  zabbix_log(LOG_LEVEL_CRIT, "[file:%s,line:%d] zbx_malloc: out of memory. Requested " ZBX_FS_SIZE_T " bytes.",
      filename, line, (zbx_fs_size_t)size);

  exit(EXIT_FAILURE);
}
void  *zbx_realloc2(const char *filename, int line, void *old, size_t size)
{
  int max_attempts;
  void  *ptr = NULL;

  for (
    max_attempts = 10, size = MAX(size, 1);
    0 < max_attempts && NULL == ptr;
    ptr = realloc(old, size), max_attempts--
  );

  if (NULL != ptr)
    return ptr;

  zabbix_log(LOG_LEVEL_CRIT, "[file:%s,line:%d] zbx_realloc: out of memory. Requested " ZBX_FS_SIZE_T " bytes.",
      filename, line, (zbx_fs_size_t)size);

  exit(EXIT_FAILURE);
}

ref: zabbix/misc.c at b93f5c4fc09286ec199910c7d450b8a4bf4dd3de · zabbix/zabbix · GitHub

このように書かれている.まずこの周辺の処理に問題がある可能性がある.

また,別の観点では,このmalloc()realloc()をcallする際,ポインタとsizeを引数として渡している事がわかる.
このポインタやsizeが不適切に設定されている可能性も考えられる.

結論から述べると,これはcallする側に問題があった.
debugをすすめていくと,Valgrindのリーク元として記載されている関数であるVFS_FILE_CONTENTSのうち,このzbx_readを用いた判定がwhileループを抜けることなく不自然に繰り返されている事に気がついた. 本来であればこのロジックはzbx_read()でファイルディスクリプタからbufferに取り込み,utf8に文字コード変換をしcontentsとして保存するようなロジックであると考えられ,whileを複数回繰り返すことはあれど,zbx_read()からの戻り値が常に返却されることは考えにくい. ここからたどっていき,zbx_read()が返却するnbytesが不適切に返却されている可能性が高いことがわかった.

int zbx_read(int fd, char *buf, size_t count, const char *encoding)
{
  size_t    i, szbyte, nbytes;
  const char  *cr, *lf;
  zbx_offset_t  offset;

  if ((zbx_offset_t)-1 == (offset = zbx_lseek(fd, 0, SEEK_CUR)))
    return -1;

  if (0 >= (nbytes = read(fd, buf, (unsigned int)count)))
    return (int)nbytes;

  find_cr_lf_szbyte(encoding, &cr, &lf, &szbyte);

  for (i = 0; i <= nbytes - szbyte; i += szbyte)
  {
    if (0 == memcmp(&buf[i], lf, szbyte)) /* LF (Unix) */
    {
      i += szbyte;
      break;
    }

    if (0 == memcmp(&buf[i], cr, szbyte)) /* CR (Mac) */
    {
      /* CR+LF (Windows) ? */
      if (i < nbytes - szbyte && 0 == memcmp(&buf[i + szbyte], lf, szbyte))
        i += szbyte;

      i += szbyte;
      break;
    }
  }

  if ((zbx_offset_t)-1 == zbx_lseek(fd, offset + (zbx_offset_t)i, SEEK_SET))
    return -1;

  return (int)i;
}

ref: zabbix/file.c at b93f5c4fc09286ec199910c7d450b8a4bf4dd3de · zabbix/zabbix · GitHub

このどこかで不適切なreturnが存在する可能性がある.
前述の通りwhileループを抜けることなく繰り返していることから,正の値の返却があり,可能性は2つに絞られる. 最後の

return (int)i;

もしくは10行目の

  if (0 >= (nbytes = read(fd, buf, (unsigned int)count)))
    return (int)nbytes;

である.

可能性としてかなり絞られたのでprintf debugしかり,logとして出力してdebugした.

int  zbx_read(int fd, char *buf, size_t count, const char *encoding)
{
  size_t          i, szbyte, nbytes;
  const char      *cr, *lf;
  zbx_offset_t    offset;

  if ((zbx_offset_t)-1 == (offset = zbx_lseek(fd, 0, SEEK_CUR)))
          return -1;

  if (0 >= (nbytes = read(fd, buf, (unsigned int)count)))
  {
          zabbix_log(LOG_LEVEL_CRIT, "zbx_read: read() returned: %d nbytes", (int)nbytes);
          return (int)nbytes;
  }

  find_cr_lf_szbyte(encoding, &cr, &lf, &szbyte);

  for (i = 0; i <= nbytes - szbyte; i += szbyte)
  {
          if (0 == memcmp(&buf[i], lf, szbyte))   /* LF (Unix) */
          {
                  i += szbyte;
                  break;
          }

          if (0 == memcmp(&buf[i], cr, szbyte))   /* CR (Mac) */
          {
                  /* CR+LF (Windows) ? */
                  if (i < nbytes - szbyte && 0 == memcmp(&buf[i + szbyte], lf, szbyte))
                          i += szbyte;

                  i += szbyte;
                  break;
          }
  }

  if ((zbx_offset_t)-1 == zbx_lseek(fd, offset + (zbx_offset_t)i, SEEK_SET))
          return -1;

  zabbix_log(LOG_LEVEL_CRIT, "zbx_read: zbx_read() returned: %d nbytes", i);
  return (int)i;
}

returnの直前にreturnとして返却する値をlogに表示した.
得られた結果はこうだ.

19207:20191202:093521.406 zbx_read: read() returned: -1 nbytes
19207:20191202:093521.406 zbx_read: zbx_read() returned: 66 nbytes

気づくべきなのは1行目.

  if (0 >= (nbytes = read(fd, buf, (unsigned int)count)))
  {
          zabbix_log(LOG_LEVEL_CRIT, "zbx_read: read() returned: %d nbytes", (int)nbytes);
          return (int)nbytes;
  }

というブロックに対して

19207:20191202:093521.406 zbx_read: read() returned: -1 nbytes

というログが出力されている.

意図としてはread()からのreturn値が0以上である場合if内部を実行する.
具体的にはzabbix_log()を実行し(int)nbytesをreturnするようなロジックを書きたいと考えられる.

しかしこのログ出力からは,return値が-1であるにも関わらずログに出力されている(if内部が実行されている).
このことからキャストが不足している可能性があることに気づく. 軽率に

  if (0 >= (int)(nbytes = read(fd, buf, (unsigned int)count)))
  {
          zabbix_log(LOG_LEVEL_CRIT, "zbx_read: read() returned: %d nbytes", (int)nbytes);
          return (int)nbytes;
  }

とintキャストしてコンパイル,実行したところ,このメモリリークが解消された. 原因はnbytessize_tとして宣言されていたことによりread()のreturnが-1である場合でも正の値として判定されているところにあった.
これによりreturnされるべきでない-1というread()からの返り値が正の値としてint castされて返却されてしまいVFS_FILE_CONTENTS()におけるwhileでの異常なループが起きていたと考えられる.

上記の内容から原因はzbx_read内部における不適切な値返却だとわかった.

これらの内容をzabbix communityにbug patchとして報告した.まぁ実際はreviewerが色々訂正してくれたからbug report程度なんだけど. f:id:jp7fkf:20200520224911p:plain

内容を読んだ人はわかると思うが,当初私はValgrindの出力から,zbx_strncpy_alloc() 内部で利用されているzbx_malloc2(), zbx_realloc2()に問題があるのではないかと信じ込み,不適切な報告をしてしまっている. しかし対応していただいたレビューアには,「その部分は問題ないように見える」と優しく教えてもらった. のちに手元で検証したところ,やはり問題はなく,自分のc言語に対する理解力の不足と思い込みがこのミスを招いている.

しかしそれとは別に私は上記のcast不足を提言し,改善したコードの提示をした. そのコードはレビュアーによってより改善(具体的にはsize_t型(unsigned)として宣言されていたnbytesssize_t(signed)として定義するように変更)され,このメモリリークのbugは解消された.

めでたしめでたし.
これによって私の身の回りのメモリリークは落ち着いた.よかった.

また,これをきっかけにVFS_FILE_CONTENTS 内で2箇所memory leakの危険性があることがわかり,ついでになおしてもらった.これに気づいたのはreviewerだったけど,この報告がきっかけになっていたのはうれしい.

P.S. BugfixとしてChangelogに名前載せてくれた.ありがとう!
f:id:jp7fkf:20200520224920p:plain

まとめ

いつもお世話になってるzabbixに1nmくらいは貢献した気分.
OSSへの貢献ってなかなか技術力がない自分には難しいところがあるが,やれる部分でなんとか協力してやっていきたい.
また不適切な報告をしたのは大変申し訳ない事案であったので技術力をもうちょい高めていきたい.
C言語ぜんぜんわかってなくてすまん」といったらありがたいお言葉をいただいた.気が休まる思い.ありがたい. f:id:jp7fkf:20200520224916p:plain:w400

なんにせよリークが治って個人的には助かった.
英語でbugの議論したりするの,ちょっと楽しかった.まだまだだけど.
つい先日zabbix5.0がリリースされて,zabbix-agent2というgoで書かれた新しいagentも登場している.このcで書かれたagentがいつまで使われるのかわからないが,しばらくは使われる気もする.なんにせよ人に使われるものに1nmでも貢献できたことが嬉しい.
そういえばValgrindをつかってこうやってまともにメモリリークを調べたのも初めてのことだったっぽい.意外となんとかなるものだ.

Special Thanks(Reviewer)!

  • Glebs Ivanovskis
  • Andris Mednis
  • Martins Abele

References

Ubuntu18.04にELK Stackを構成する

概要

  • Ubuntu18.04に
  • Elasticsearch(7.7)まわりのdebパッケージを
  • aptレポジトリから引っ張ってきて
  • インストールして
  • Logstash(log insert) -> Elasticsearch(processiog) <-> Kibana(visualize)ができる ところまでを実施します.

基本的に下記を参照します

Elastic Stack Install Battle

Install PGP key

$ wget -qO - https://artifacts.elastic.co/GPG-KEY-elasticsearch | sudo apt-key add -
OK

add repository to apt source list

$ echo "deb https://artifacts.elastic.co/packages/7.x/apt stable main" | sudo tee -a /etc/apt/sources.list.d/elastic-7.x.list
deb https://artifacts.elastic.co/packages/7.x/apt stable main

Install Elasticsearch

$ sudo apt update
$ sudo apt install elasticsearch
$ sudo apt install elasticsearch
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following NEW packages will be installed:
  elasticsearch
0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded.
Need to get 314 MB of archives.
After this operation, 527 MB of additional disk space will be used.
Get:1 https://artifacts.elastic.co/packages/7.x/apt stable/main amd64 elasticsearch amd64 7.7.0 [314 MB]
Fetched 314 MB in 5min 57s (881 kB/s)
Selecting previously unselected package elasticsearch.
(Reading database ... 116882 files and directories currently installed.)
Preparing to unpack .../elasticsearch_7.7.0_amd64.deb ...
Creating elasticsearch group... OK
Creating elasticsearch user... OK
Unpacking elasticsearch (7.7.0) ...
Setting up elasticsearch (7.7.0) ...
Created elasticsearch keystore in /etc/elasticsearch/elasticsearch.keystore
Processing triggers for ureadahead (0.100.0-21) ...
Processing triggers for systemd (237-3ubuntu10.40) ...

ここまででelasticsearch自体のインストール自体は完了.

  • ヒープサイズのconfig
    JVMで使わせるヒープサイズをチューンする.一般には物理メモリの約半分を割り当てればいいそう. ただし32GBらへんに圧縮オブジェクトポインタのしきい値があるらしく,だいたい26GB以下にしておけば安全そう.
  • ref: Setting the heap size | Elasticsearch Reference [7.7] | Elastic
    今回は物理メモリとして16GB割り当てているので8GBにしておく.
$ sudo cat /etc/elasticsearch/jvm.options | head -30
## JVM configuration

################################################################
## IMPORTANT: JVM heap size
################################################################
##
## You should always set the min and max JVM heap
## size to the same value. For example, to set
## the heap to 4 GB, set:
##
## -Xms4g
## -Xmx4g
##
## See https://www.elastic.co/guide/en/elasticsearch/reference/current/heap-size.html
## for more information
##
################################################################

# Xms represents the initial size of total heap space
# Xmx represents the maximum size of total heap space

-Xms8g
-Xmx8g

################################################################
## Expert settings
################################################################
##
## All settings below this section are considered
## expert settings. Don't tamper with them unless
$ sudo vim /etc/elasticsearch/elasticsearch.yml
# ---------------------------------- Network -----------------------------------
#
# Set the bind address to a specific IP (IPv4 or IPv6):
#
network.host: <bind_ip>
#
# Set a custom port for HTTP:
#
http.port: 9200
#
# For more information, consult the network module documentation.

脳死したければ network.host: "0.0.0.0"とか入れておけばいいと思う.v6なら network.host: "::0"とか?

  • 起動してみる.
    構築したホスト上でcurl "http://localhost:9200/" を打つと実際にelasticsearchにアクセスすることができる.
$ sudo systemctl start elasticsearch.service
$ sudo systemctl enable elasticsearch.service
$ sudo systemctl status elasticsearch.service
● elasticsearch.service - Elasticsearch
   Loaded: loaded (/usr/lib/systemd/system/elasticsearch.service; disabled; vendor preset: enabled)
   Active: active (running) since Sat 2020-05-16 14:33:17 UTC; 1 day 13h ago
     Docs: https://www.elastic.co
 Main PID: 3301 (java)
    Tasks: 83 (limit: 4915)
   CGroup: /system.slice/elasticsearch.service
           ├─3301 /usr/share/elasticsearch/jdk/bin/java -Xshare:auto -Des.networkaddress.cache.ttl=60 -Des.networkadd
           └─3505 /usr/share/elasticsearch/modules/x-pack-ml/platform/linux-x86_64/bin/controller

May 16 14:33:01 elk01 systemd[1]: Starting Elasticsearch...
May 16 14:33:17 elk01 systemd[1]: Started Elasticsearch.

$ curl "http://localhost:9200/"
{
  "name" : "ela01",
  "cluster_name" : "elc01",
  "cluster_uuid" : "xxxxxxxxxxxxxxxxxxxxxx",
  "version" : {
    "number" : "7.7.0",
    "build_flavor" : "default",
    "build_type" : "deb",
    "build_hash" : "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx",
    "build_date" : "2020-05-12T02:01:37.602180Z",
    "build_snapshot" : false,
    "lucene_version" : "8.5.1",
    "minimum_wire_compatibility_version" : "6.8.0",
    "minimum_index_compatibility_version" : "6.0.0-beta1"
  },
  "tagline" : "You Know, for Search"
}
  • [つぶやき]: javaをinstallしてないのに動いたなーと思ったらelasticsearchのパッケージを入れるとjavaも一緒に入ってくるっぽい
$ /usr/share/elasticsearch/jdk/bin/java --version
openjdk 13.0.2 2020-01-14
OpenJDK Runtime Environment AdoptOpenJDK (build 13.0.2+8)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 13.0.2+8, mixed mode, sharing)

debパッケージをdpkgでいれたりtarballで引っ張ってきて展開したjavaまでついてくるかは知らない. 前はaptでも別にjdk入れないといけなかった気がしたけど,もう忘れてしまった.少なくとも最近のaptからのinstallでは一緒についてくるらしい.
- Elastic Support Matrix | Elasticsearch
と思ったらこれのサポートはあくまでelasticsearchを動かすだけにすぎなかった.elasticsearch本体だけなら動くけどlogstashとかはこのjdk verでは動かない. javaまでのpathが通ってない(and JAVA_HOMEが適切に環境変数に設定されていないと)こんな感じでapt installでerrorを吐く.

$ sudo apt install logstash
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following NEW packages will be installed:
  logstash
0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded.
Need to get 167 MB of archives.
After this operation, 295 MB of additional disk space will be used.
Get:1 https://artifacts.elastic.co/packages/7.x/apt stable/main amd64 logstash all 1:7.7.0-1 [167 MB]
Fetched 167 MB in 4min 54s (569 kB/s)
Selecting previously unselected package logstash.
(Reading database ... 103575 files and directories currently installed.)
Preparing to unpack .../logstash_1%3a7.7.0-1_all.deb ...
Unpacking logstash (1:7.7.0-1) ...
Setting up logstash (1:7.7.0-1) ...
could not find java; set JAVA_HOME or ensure java is in PATH
chmod: cannot access '/etc/default/logstash': No such file or directory
dpkg: error processing package logstash (--configure):
 installed logstash package post-installation script subprocess returned error exit status 1

なのでやっぱりELK stackを構築するなら
$ sudo apt install openjdk-8-jre
するのが正解.最近のELKコンポーネントだとopenjdk-11でもいいっぽいけどまぁ好きなの使えばいい気がする.ただjdk9以降はaptとかでさくっと入らないっぽく見えるからめんどそう.

Install logstash and Kibana

$ java -version
openjdk version "1.8.0_252"
OpenJDK Runtime Environment (build 1.8.0_252-8u252-b09-1~18.04-b09)
OpenJDK 64-Bit Server VM (build 25.252-b09, mixed mode)

javaが入ってる(PATHが通る)ことを確認して

sudo apt install logstash
sudo apt install kibana

でさくっとはいる.javaへのPATHが通ってないと失敗するので注意.

  • kibanaのconfig
$ sudo vim /etc/kibana/kibana.yml
server.port: 5601
server.host: "<bind_ip>"
elasticsearch.hosts: ["http://localhost:9200"]

<bind_ip>には前述のとおりlistenするipを入れる.

  • logstashのconfig
$ sudo vim /etc/logstash/jvm.options
-Xms8g
-Xmx8g
  • 起動
$ sudo systemctl start logstash
$ sudo systemctl start kibana
$ sudo systemctl enable logstash
$ sudo systemctl enable kibana

$ sudo systemctl status logstash
● logstash.service - logstash
   Loaded: loaded (/etc/systemd/system/logstash.service; disabled; vendor preset: enabled)
   Active: active (running) since Sat 2020-05-16 15:33:30 UTC; 1 day 11h ago
 Main PID: 7282 (java)
    Tasks: 43 (limit: 4915)
   CGroup: /system.slice/logstash.service
           └─7282 /usr/bin/java -Xms4g -Xmx4g -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseC
...(snip)...

$ sudo systemctl status kibana
● kibana.service - Kibana
   Loaded: loaded (/etc/systemd/system/kibana.service; enabled; vendor preset: enabled)
   Active: active (running) since Sat 2020-05-16 14:40:41 UTC; 1 day 12h ago
 Main PID: 4569 (node)
    Tasks: 11 (limit: 4915)
   CGroup: /system.slice/kibana.service
           └─4569 /usr/share/kibana/bin/../node/bin/node /usr/share/kibana/bin/../src/cli -c /etc/kibana/kibana.yml
...(snip)...

ex. syslog insert to elasticsearch via logstash

syslogをlogstash経由でelasticsearchにいれてkibanaでみるところまでをやってみる. まずはsyslog pluginをlogstash-pluginを使って入れる.

$ /usr/share/logstash/bin/logstash-plugin list syslog
logstash-filter-syslog_pri
logstash-input-syslog
$ /usr/share/logstash/bin/logstash-plugin install logstash-input-syslog
ERROR: File /usr/share/logstash/Gemfile does not exist or is not writable, aborting
$ sudo /usr/share/logstash/bin/logstash-plugin install logstash-input-syslog
Validating logstash-input-syslog
Installing logstash-input-syslog
Installation successful

次にlogstashのconfigを作っていく. 適当にsyslogを受ける例を書くとこんな感じ.

$ cat /etc/logstash/conf.d/01-syslog.conf
input {
  syslog {
      port => 10514
      type => "syslog"
  }
}

filter {
} # filter

output {
  if "syslog" in [type] {
    elasticsearch {
      hosts => ["localhost:9200"]
      index => "logstash-syslog"
   }
    # stdout { codec => rubydebug }
  }
}

ポート番号1024以下はpriviledgedなのでroot権限等がないとpermission deniedで弾かれる.
rootで実行するのも一つの手ではあるが,下記などではport forward(redirect)する例が挙げられている.
今回は10514としてそのまま利用する.

configを書いたらlogstash をrestartする.logstashの嫌なところはこのconfigを変えたらrestartする必要があるところ. 前段にkafkaなどのqueueをいれたりするのがこのrestartによるデータ欠損回避手段のうちの一つかもしれない.

$ sudo systemctl restart logstash

さて,ここまででlogstash -> elasticsearch ->kibanaのパイプラインが完成した.
実際にlogを突っ込んで見る.

logger -n localhost -P 10514 -t mytest -p user.notice --rfc3164 "TEST LOG"

これで送られた"はず"である.

ここからはkibanaでみていこう.
kibanaへはconfigした通り,デフォルトでは5601ポートでアクセスする.
kibanaでデータを取り扱う上でまずindex-patternを作る必要がある. Management -> Index Managementでelasticsearch側に先程のsyslogのindexが作成されていることを確認.
これがないとindex patternを作っても見れない.これがない場合elasticsearchに正常にinsertされていない可能性が高いのでまずはそのdebugをしよう.
この画面ではlogstashのconfigでindexとして指定したlogstash-syslogが見えている. f:id:jp7fkf:20200518215937p:plain elasticsearchにindexがあることが確認できたら,今度はkibana側のindex patternsを見る デフォルトだと何も登録されていないので,Create Index Patternを押す f:id:jp7fkf:20200518220014p:plain するとelasticsearchのindexが候補で見えてくる. f:id:jp7fkf:20200518220020p:plain index patternの定義をするので,textboxにindex patternの名前(ワイルドカード可)を入れて1つに絞る.
ここではlogstash-syslogそのまま入れると一つに絞ることができるのでNext Stepが押せるようになる. f:id:jp7fkf:20200518220026p:plain 次にtime filter firldを指定する.ここではlogstashでつける@timestampをそのまま使う. これでCreate Index Patternを押す. f:id:jp7fkf:20200518220046p:plain するとIndexがつくられて f:id:jp7fkf:20200518220031p:plain Index Patternのできあがり. f:id:jp7fkf:20200518220035p:plain discover画面に行って確認すると,無事先ほどのloggerコマンドで転送したログが見える. f:id:jp7fkf:20200518220040p:plain

ここまでで一通りELKスタックを用いてsyslogをkibanaで見えるようになった.

 まとめ

  • Ubuntu18.04にElastic Stack (ELK, Logstash, Elasticsearch, Kibana)をaptパッケージを用いて構築した
  • Logstash(log insert) -> Elasticsearch(processiog) <-> Kibana(visualize)のパイプラインにsyslogを投入しkibanaで観測した.

logstashにはこの他にも色々なpluginがあり,様々なデータをELKスタックを用いてデータ分析/可視化することができる . また,logstash以外にもelasticsearchへの出力機能を持ったコンポーネント(ex. fluentd)などが数多くあるので,それらとうまく組み合わせて柔軟な分析基盤の構成ができそうである.

個人的にはDHCPサーバのリースログからクライアントのMACアドレスのベンダコード(OUI)をもとにベンダをを可視化したり,xflow(sflow/netflow)を食わせてgeo-ipの緯度経度データとIPアドレスを突き合わせてどの国/regionとの通信が多いのかを可視化したりすることもやってみたが,なかなかおもしろい. flowデータをもとにすれば通信をポート番号ベースで可視化したりすることができ,特定ポート宛などのDDoSの検知や内部から外部への不正な大量トラフィック(マルウェア感染端末からのDNS Amp.など)の検出もできそうである.可視化で得られた異常なデータをクリックすることでそのデータの詳細なレコードもkibanaならすぐに見ることができてユーザ体験はとてもよい.
可視化することは人間に直感的にあらゆる物事を短時間で理解させることを手助けする大きな価値のある手法であると思うので,是非このような可視化/分析ツール活用していきたいものである.